Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TestPeople is really, really broken #274

Closed
KyleMaas opened this issue Dec 23, 2022 · 23 comments · Fixed by #322
Closed

TestPeople is really, really broken #274

KyleMaas opened this issue Dec 23, 2022 · 23 comments · Fixed by #322
Labels
testing

Comments

@KyleMaas
Copy link
Contributor

Just doing the excerpts for the failing tests, because this test suite has a lot of individual tests. Also...there are a lot more failures. This one is very, very broken. You don't even have to really try to make this fail. But what's worse is that it appears that some of these failures are not actually marking tests as FAILed, so it wouldn't show up in a CI run's report as anything more than logged messages.

See #237

=== RUN   TestPeople/negative_hops/badger
    people_test.go:62: created(38) alice as @7jHOZszoMSOyB9maZORSYnzOIXrWSJaZDJqfwG1OU/c=.ed25519 (algo:ed25519)
    people_test.go:62: created(39) bob as @xfKhHxHPYqlMeJ0aWznFANeUte7QHQ1znkwEEPE91e0=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/negative_hops/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/negative_hops/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x89544b]

goroutine 1041 [running]:
github.com/dgraph-io/badger/v3.(*memTable).IncrRef(...)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/memtable.go:231
github.com/dgraph-io/badger/v3.(*DB).getMemTables(0xc00dee6480)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:696 +0x12b
github.com/dgraph-io/badger/v3.(*DB).get(0xc00dee6480, {0xc00ded2000, 0x27, 0x27})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:730 +0x9d
github.com/dgraph-io/badger/v3.(*Txn).Get(0xc0022f4080, {0xc000024100, 0x1f, 0x20})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:478 +0x2a7
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq.func1(0xc00dee6480?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:387 +0x32
github.com/dgraph-io/badger/v3.(*DB).View(0xc00dece1b8?, 0xc0022aee10)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:806 +0x9c
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq(0xc0024b4140)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:386 +0x198
github.com/ssbc/margaret/indexes.(*sinkIndex).QuerySpec(0x0?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/sinkindex.go:30 +0x25
github.com/ssbc/go-ssb/graph.serveLog.func1()
        /home/go-ssb/go-ssb/graph/builder_test.go:330 +0xdd
created by github.com/ssbc/go-ssb/graph.serveLog
        /home/go-ssb/go-ssb/graph/builder_test.go:327 +0x165
FAIL    github.com/ssbc/go-ssb/graph    1.648s
FAIL

=== RUN   TestPeople/unfollow/badger
    people_test.go:62: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:62: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:62: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
level=warn t=24.605214ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(bob) (dist:0)
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #3 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
level=warn t=24.962874ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #5 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x89544b]

goroutine 129 [running]:
github.com/dgraph-io/badger/v3.(*memTable).IncrRef(...)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/memtable.go:231
github.com/dgraph-io/badger/v3.(*DB).getMemTables(0xc0000f7b00)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:696 +0x12b
github.com/dgraph-io/badger/v3.(*DB).get(0xc0000f7b00, {0xc0187a74d0, 0x27, 0x27})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:730 +0x9d
github.com/dgraph-io/badger/v3.(*Txn).Get(0xc018753080, {0xc000025380, 0x1f, 0x20})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:478 +0x2a7
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq.func1(0xc0000f7b00?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:387 +0x32
github.com/dgraph-io/badger/v3.(*DB).View(0xc00de68cd8?, 0xc0022f0e10)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:806 +0x9c
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq(0xc00cda8320)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:386 +0x198
github.com/ssbc/margaret/indexes.(*sinkIndex).QuerySpec(0x0?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/sinkindex.go:30 +0x25
github.com/ssbc/go-ssb/graph.serveLog.func1()
        /home/go-ssb/go-ssb/graph/builder_test.go:330 +0xdd
created by github.com/ssbc/go-ssb/graph.serveLog
        /home/go-ssb/go-ssb/graph/builder_test.go:327 +0x165
FAIL    github.com/ssbc/go-ssb/graph    0.104s
FAIL

=== RUN   TestPeople/friends2/badger
    people_test.go:62: created(11) alice as @QgppJkKXvISpSREEymrm6Eo8ueXdCEsT4NXLblMFNbQ=.ed25519 (algo:ed25519)
    people_test.go:62: created(12) bob as @M/i2gniJ9pXbZUVLzZlJcVTF35YuHdEazGykNWFcioc=.ed25519 (algo:ed25519)
    people_test.go:62: created(13) claire as @Rxiw1qV63OL3ltw5UoBAeNLS2mYuBPNvjRt08nf+DzM=.ed25519 (algo:ed25519)
    people_test.go:62: created(14) debora as @eKiXUgaRPSdK14Ho2tWGtz88yZrhJTgGwZZohgiYPyE=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/friends2/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/friends2/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/friends2/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/friends2/badger
                Messages:       did not find peer debora in graph lookup table (len:0)
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/friends2/badger
                Messages:       assertion #1 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/friends2/badger
                Messages:       assertion #2 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/friends2/badger
                Messages:       assertion #3 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                dist: make dijkstra failed: ssb/graph: no such from: @QgppJkKXvISpSREEymrm6Eo8ueXdCEsT4NXLblMFNbQ=.ed25519
                Test:           TestPeople/friends2/badger
                Messages:       assertion #4 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
level=warn t=140.690909ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(debora) (dist:0)
                Test:           TestPeople/friends2/badger
                Messages:       assertion #5 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
level=warn t=141.095554ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(debora) (dist:1)
                Test:           TestPeople/friends2/badger
                Messages:       assertion #6 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
level=warn t=141.526452ms msg="authbypass - trust on first use"
    builder_test.go:131: closed scenary

=== RUN   TestPeople/blocks/badger
    people_test.go:62: created(15) alice as @KUM9tEHEDsySlDkbujU1NzGccf+x926aKgZvwCC5HyE=.ed25519 (algo:ed25519)
    people_test.go:62: created(16) bob as @029ZcpU14U1WceWigylZE8vP/sazYiaozZcAt0Ymoo8=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/blocks/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/blocks/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                Blocks() assert failed - wanted true
                Test:           TestPeople/blocks/badger
                Messages:       assertion #2 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
    builder_test.go:131: closed scenary

=== RUN   TestPeople/blocks/badger
    people_test.go:62: created(15) alice as @KUM9tEHEDsySlDkbujU1NzGccf+x926aKgZvwCC5HyE=.ed25519 (algo:ed25519)
    people_test.go:62: created(16) bob as @029ZcpU14U1WceWigylZE8vP/sazYiaozZcAt0Ymoo8=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/blocks/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/blocks/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                Blocks() assert failed - wanted true
                Test:           TestPeople/blocks/badger
                Messages:       assertion #2 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
    builder_test.go:131: closed scenary

=== RUN   TestPeople/negative_hops/badger
    people_test.go:62: created(38) alice as @7jHOZszoMSOyB9maZORSYnzOIXrWSJaZDJqfwG1OU/c=.ed25519 (algo:ed25519)
    people_test.go:62: created(39) bob as @xfKhHxHPYqlMeJ0aWznFANeUte7QHQ1znkwEEPE91e0=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/negative_hops/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/negative_hops/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x89544b]

goroutine 1044 [running]:
github.com/dgraph-io/badger/v3.(*memTable).IncrRef(...)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/memtable.go:231
github.com/dgraph-io/badger/v3.(*DB).getMemTables(0xc0048a2480)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:696 +0x12b
github.com/dgraph-io/badger/v3.(*DB).get(0xc0048a2480, {0xc002ba3260, 0x27, 0x27})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:730 +0x9d
github.com/dgraph-io/badger/v3.(*Txn).Get(0xc00027aa80, {0xc000024640, 0x1f, 0x20})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:478 +0x2a7
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq.func1(0xc0048a2480?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:387 +0x32
github.com/dgraph-io/badger/v3.(*DB).View(0xc00303c008?, 0xc000052e10)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:806 +0x9c
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq(2022/12/23 01:42:17 [margaret/indexes/badger] overwrote batch limit 0

=== RUN   TestPeople/hops_2/badger
    people_test.go:62: created(50) alice as @lfWnBH2njS/EDO6gQ+/182Xk4h/GStHpCNRXP5y2mZE=.ed25519 (algo:ed25519)
    people_test.go:62: created(51) bob as @P/VGLvjY+edi4/zbtMEzq7nw64hWfCPQdwbfiFhGt/g=.ed25519 (algo:ed25519)
    people_test.go:62: created(52) claire as @q1JrC8V4q5iRmUW0N2mryqRkzPdKhe0Cs1rUSGTORfI=.ed25519 (algo:ed25519)
    people_test.go:62: created(53) bobf1 as @LuJzhWvs47r/j+wv611wgH3gBtyCoJWVRfFNqGFi6K8=.ed25519 (algo:ed25519)
    people_test.go:62: created(54) bobf2 as @5iFR8+Pifnya6epCY2aRRoIT+5RdmbYWF2JsJ8lyYaU=.ed25519 (algo:ed25519)
    people_test.go:62: created(55) bobfam1 as @pgm1G9v8fvH/nZhil5hzBevBEFQfr3u52TmU0iGJnf4=.ed25519 (algo:ed25519)
    people_test.go:62: created(56) bobfam2 as @l3AxD6A6pBRhdS9742bSq0R59yJsBn9xyml5wqDg94I=.ed25519 (algo:ed25519)
    people_test.go:62: created(57) bobfam3 as @O+qANDVqY/k32q7P8cGvod140D3AcazTTxRzpF46rsA=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/hops_2/badger
                Messages:       did not find peer claire in graph lookup table (len:7)
    hops_test.go:125:
                Error Trace:    /home/go-ssb/go-ssb/graph/hops_test.go:125
                                                        /home/go-ssb/go-ss2022/12/23 01:42:36 [margaret/indexes/badger] overwrote batch limit 0

=== RUN   TestPeople/unfollow/badger
    people_test.go:62: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:62: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:62: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
    people_test.go:265:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:265
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
level=warn t=32.77289ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(bob) (dist:0)
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #3 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
level=warn t=33.802143ms msg="authbypass - trust on first use"
    people_test.go:274:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:274
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #5 failed
    people_test.go:278: warning: failed to dump graph to SVG RenderSVG: dot command failed: exec: "dot": executable file not found in $PATH
2022/12/23 01:42:36 got err for badgerContacts error pouring read value of seq(0): error calling setter func: db/idx contacts: failed to update index. {Type: Contact:@rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 Following:true Blocking:false}: failed to write big batch (1): error in badger transaction (update) 1: Writes are blocked, possibly due to DropAll or Close
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x89544b]

goroutine 131 [running]:
github.com/dgraph-io/badger/v3.(*memTable).IncrRef(...)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/memtable.go:231
github.com/dgraph-io/badger/v3.(*DB).getMemTables(0xc000153b00)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:696 +0x12b
github.com/dgraph-io/badger/v3.(*DB).get(0xc000153b00, {0xc0187bb830, 0x27, 0x27})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:730 +0x9d
github.com/dgraph-io/badger/v3.(*Txn).Get(0xc000204280, {0xc0000243a0, 0x1f, 0x20})
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:478 +0x2a7
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq.func1(0xc000153b00?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:387 +0x32
github.com/dgraph-io/badger/v3.(*DB).View(0xc00ce7c8a0?, 0xc00cd80e10)
        /home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/txn.go:806 +0x9c
github.com/ssbc/margaret/indexes/badger.(*index).GetSeq(0xc0001ce5a0)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:386 +0x198
github.com/ssbc/margaret/indexes.(*sinkIndex).QuerySpec(0x0?)
        /home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/sinkindex.go:30 +0x25
github.com/ssbc/go-ssb/graph.serveLog.func1()
        /home/go-ssb/go-ssb/graph/builder_test.go:330 +0xdd
created by github.com/ssbc/go-ssb/graph.serveLog
        /home/go-ssb/go-ssb/graph/builder_test.go:327 +0x165
FAIL    github.com/ssbc/go-ssb/graph    0.129s
FAIL
@KyleMaas
Copy link
Contributor Author

I think this one is beyond my abilities for the moment.

@decentral1se decentral1se mentioned this issue Dec 26, 2022
Open
25 tasks
@decentral1se
Copy link
Member

decentral1se commented Dec 28, 2022 •
edited
Loading

A wild amount of errors! You're an inspiration @KyleMaas 🤣

@KyleMaas
Copy link
Contributor Author

Heh...thanks. Just wish my capabilities were such that I could tackle some of the more complicated breakage like this.

@decentral1se decentral1se moved this from In Progress to TODO in 🚧 go-ssb maintenance 🚧 Jan 10, 2023
@decentral1se decentral1se moved this from TODO to Prioritised in 🚧 go-ssb maintenance 🚧 Jan 10, 2023
@KyleMaas
Copy link
Contributor Author

I think #313 may have fixed this one. That had a bunch of fixes for the graph subsystem. Will have to check.

@KyleMaas
Copy link
Contributor Author

It did not. Not sure why yet.

@KyleMaas
Copy link
Contributor Author

I've got a WaitGroup added to multilogs to protect UserFeedsUpdate, and that still didn't fix it. In one of my test runs, the graph seemed to contain no data at all, despite only generating the graph after both the builder and multilogs should have theoretically completely finished indexing everything. So there appears to be another race condition somewhere else.

@KyleMaas
Copy link
Contributor Author

Another note: I'm sure a delay between the Ops and the Asserts in TestPeople would fix this. But that seems like a terrible solution. We need a way to guard against these race conditions, not (both in the tests and in our expectations of users) to wait and hope they go away.

Just wanted to take some notes on debugging progress since it may be a little bit before I can come back to this one.

@KyleMaas
Copy link
Contributor Author

Tried turning UserFeedsUpdate into a CreateUserFeedsUpdateSink function which would also work with a WaitGroup to synchronize. It didn't fix the problem.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

Tried adding a full second of delay between the Ops and the Asserts. It did not fix the problem. It's looking like it's not just a race condition with the indexes but is instead very broken in some other non-time-dependent way.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

Even with 10 seconds of delay, it still fails.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

It seems there is a higher percentage of failures when the delay is longer.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

One example failed test run:

=== RUN   TestPeople/unfollow/badger
level=warn t=45.982732ms msg="sync start"
level=warn t=46.028049ms msg="sync start"
level=warn t=46.050962ms msg="sync start"
level=warn t=46.060792ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=52.766961ms msg="sync start"
level=warn t=53.042328ms msg="sync start"
level=warn t=53.419764ms msg="sync start"
level=warn t=53.627268ms msg="sync start"
level=warn t=146.797953ms msg="sync done"
level=warn t=146.97726ms msg="sync done"
level=warn t=147.008267ms msg="sync done"
level=warn t=147.027705ms msg="sync done"
level=warn t=152.788664ms msg="waiting for sync"
level=warn t=152.902715ms msg="sync done"
level=warn t=154.105649ms msg="sync done"
level=warn t=154.233104ms msg="sync done"
level=warn t=154.29131ms msg="sync done"
level=warn t=154.373742ms msg="done waiting for sync"
t=154.427548ms event=info msg="building new graph"
t=154.506889ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
level=warn t=155.267622ms msg="waiting for sync"
level=warn t=155.304024ms msg="done waiting for sync"
t=155.369486ms event=info msg="using cached graph"
level=warn t=155.411215ms msg="waiting for sync"
level=warn t=155.44376ms msg="done waiting for sync"
t=155.473263ms event=info msg="using cached graph"
level=warn t=155.507056ms msg="waiting for sync"
level=warn t=155.536864ms msg="done waiting for sync"
t=155.56564ms event=info msg="using cached graph"
level=warn t=155.594534ms msg="authbypass - trust on first use"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(bob) (dist:0)
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #3 failed
level=warn t=243.195507ms msg="waiting for sync"
level=warn t=243.565181ms msg="done waiting for sync"
t=243.695531ms event=info msg="using cached graph"
level=warn t=243.80698ms msg="authbypass - trust on first use"
level=warn t=243.925797ms msg="waiting for sync"
level=warn t=244.034163ms msg="done waiting for sync"
t=244.1355ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #5 failed
    builder_test.go:130: closed scenary

So, what this is showing is that despite the index being up-to-date (the "sync start" and "sync done" messages are coming from builder_indexes.go processing messages into the indexes), it's only getting one message in the graph builder's iterator:

go-ssb/graph/builder.go

Line 137 in 8193f14

it := iter.Item()

Somehow things are being stored to the indexes and then not retrieved. Or maybe they're somehow all being stored under the same key. More investigation to follow. Later. That's enough for now.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

Another failed test run:

=== RUN   TestPeople/simple/badger
level=warn t=33.291965ms msg="sync start"
level=warn t=33.37952ms msg="sync start"
level=warn t=33.393632ms msg="sync start"
level=warn t=33.400716ms msg="sync start"
    people_test.go:65: created(0) alice as @O2onvM62pC1io6jQKm8Nc2UyFXcd4kOmOsBIoYtZ2ik=.ed25519 (algo:ed25519)
    people_test.go:65: created(1) bob as @BoaSQjNgS+1FWhgV6n4vLjyd4jG9NvyH7iX7WqDnFsE=.ed25519 (algo:ed25519)
    people_test.go:65: created(2) claire as @o9PNCZ9zXlYVolQTeA9g2XSmE7SJD6GGN2N0Pd/40TY=.ed25519 (algo:ed25519)
level=warn t=38.555181ms msg="sync start"
level=warn t=39.067719ms msg="sync start"
level=warn t=39.155084ms msg="sync start"
level=warn t=39.5291ms msg="sync start"
level=warn t=134.374871ms msg="sync done"
level=warn t=134.456018ms msg="sync done"
level=warn t=134.54423ms msg="sync done"
level=warn t=134.573108ms msg="sync done"
level=warn t=139.007032ms msg="sync done"
level=warn t=139.246831ms msg="sync done"
level=warn t=139.979459ms msg="sync done"
level=warn t=140.031321ms msg="sync done"
level=warn t=140.051258ms msg="waiting for sync"
level=warn t=140.086726ms msg="done waiting for sync"
t=140.0988ms event=info msg="building new graph"
t=140.149798ms event=info msg="processing message"
t=140.170913ms event=info msg="adding node from" nFrom=<@O2on.ed25519>
t=140.213982ms event=info msg="adding node to" nTo=<@o9PN.ed25519>
t=140.266928ms event=info msg="setting edge weight"
t=140.29464ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer bob in graph lookup table (len:2)
level=warn t=140.599982ms msg="waiting for sync"
level=warn t=140.634816ms msg="done waiting for sync"
t=140.649446ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/simple/badger
                Messages:       assertion #1 failed
level=warn t=186.493124ms msg="waiting for sync"
level=warn t=186.53581ms msg="done waiting for sync"
t=186.54714ms event=info msg="using cached graph"
level=warn t=186.588414ms msg="waiting for sync"
level=warn t=186.597845ms msg="done waiting for sync"
t=186.60507ms event=info msg="using cached graph"
level=warn t=186.614512ms msg="waiting for sync"
level=warn t=186.621219ms msg="done waiting for sync"
t=186.639224ms event=info msg="using cached graph"
level=warn t=186.651661ms msg="waiting for sync"
level=warn t=186.662557ms msg="done waiting for sync"
t=186.67033ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow bob
                Test:           TestPeople/simple/badger
                Messages:       assertion #5 failed
level=warn t=217.007024ms msg="waiting for sync"
level=warn t=217.047668ms msg="done waiting for sync"
t=217.0588ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

Once again showing far more things being stored to the indexes than the two messages that were retrieved when the builder was run.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

Another:

=== RUN   TestPeople/same/badger
level=warn t=92.212521ms msg="sync start"
level=warn t=92.280402ms msg="sync start"
level=warn t=92.29803ms msg="sync start"
level=warn t=92.307441ms msg="sync start"
    people_test.go:65: created(6) alice as @IAbXK85dgqUSws8+Nkj0lNmo+OCJamCUMzquZhMQOyw=.ed25519 (algo:ed25519)
    people_test.go:65: created(7) bob as @+oJKCBDx6aoZTgMRcY/6Vg37GiUkjGUfroiP8iPPJzQ=.ed25519 (algo:ed25519)
level=warn t=95.523517ms msg="sync start"
level=warn t=95.726835ms msg="sync start"
level=warn t=193.303834ms msg="sync done"
level=warn t=193.42163ms msg="sync done"
level=warn t=193.441988ms msg="sync done"
level=warn t=193.459414ms msg="sync done"
level=warn t=195.818237ms msg="waiting for sync"
level=warn t=195.890437ms msg="sync done"
level=warn t=195.952859ms msg="sync done"
level=warn t=195.996455ms msg="done waiting for sync"
t=196.027365ms event=info msg="building new graph"
t=196.117125ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/same/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/same/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
level=warn t=196.589908ms msg="waiting for sync"
level=warn t=196.601242ms msg="done waiting for sync"
t=196.609858ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/same/badger
                Messages:       assertion #1 failed
level=warn t=217.59716ms msg="waiting for sync"
level=warn t=217.710787ms msg="done waiting for sync"
t=217.727163ms event=info msg="using cached graph"
level=warn t=217.778523ms msg="waiting for sync"
level=warn t=217.7876162023/02/01 01:45:41 [margaret/indexes/badger] overwrote batch limit 0

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 1, 2023

Another:

=== RUN   TestPeople/unfollow/badger
level=warn t=43.241881ms msg="sync start"
level=warn t=43.29387ms msg="sync start"
level=warn t=43.306839ms msg="sync start"
level=warn t=43.316153ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=49.841512ms msg="sync start"
level=warn t=50.120801ms msg="sync start"
level=warn t=50.327948ms msg="sync start"
level=warn t=50.777871ms msg="sync start"
level=warn t=50.915834ms msg="sync start"
level=warn t=51.217259ms msg="sync start"
level=warn t=143.894565ms msg="sync done"
level=warn t=143.98026ms msg="sync done"
level=warn t=143.999907ms msg="sync done"
level=warn t=144.023483ms msg="sync done"
level=warn t=150.887017ms msg="sync done"
level=warn t=150.989018ms msg="sync done"
level=warn t=151.085603ms msg="sync done"
level=warn t=151.192607ms msg="sync done"
level=warn t=151.283169ms msg="sync done"
level=warn t=151.399483ms msg="sync done"
level=warn t=151.517153ms msg="waiting for sync"
level=warn t=151.577068ms msg="done waiting for sync"
t=151.636493ms event=info msg="building new graph"
t=153.613211ms event=info msg="processing message"
t=153.644971ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=153.672996ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=153.745894ms event=info msg="setting edge weight"
t=153.765036ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:2)
level=warn t=154.022353ms msg="waiting for sync"
level=warn t=154.034411ms msg="done waiting for sync"
t=154.043058ms event=info msg="using cached graph"
level=warn t=154.055662ms msg="waiting for sync"
level=warn t=154.061793ms msg="done waiting for sync"
t=154.068848ms event=info msg="using cached graph"
level=warn t=154.080331ms msg="waiting for sync"
level=warn t=154.086125ms msg="done waiting for sync"
t=154.092842ms event=info msg="using cached graph"
level=warn t=154.11757ms msg="waiting for sync"
level=warn t=154.124415ms msg="done waiting for sync"
t=154.131503ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow claire
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #4 failed
level=warn t=331.820741ms msg="waiting for sync"
level=warn t=331.863132ms msg="done waiting for sync"
t=331.87538ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

@decentral1se
Copy link
Member

😱

@KyleMaas KyleMaas mentioned this issue Feb 1, 2023
Open
@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

Added logging for every time a key is set in builder_index

=== RUN   TestPeople/simple/badger
level=warn t=48.27362ms msg="sync start"
level=warn t=48.330133ms msg="sync start"
level=warn t=48.340426ms msg="sync start"
level=warn t=48.345938ms msg="sync start"
    people_test.go:65: created(0) alice as @O2onvM62pC1io6jQKm8Nc2UyFXcd4kOmOsBIoYtZ2ik=.ed25519 (algo:ed25519)
    people_test.go:65: created(1) bob as @BoaSQjNgS+1FWhgV6n4vLjyd4jG9NvyH7iX7WqDnFsE=.ed25519 (algo:ed25519)
    people_test.go:65: created(2) claire as @o9PNCZ9zXlYVolQTeA9g2XSmE7SJD6GGN2N0Pd/40TY=.ed25519 (algo:ed25519)
level=warn t=52.389112ms msg="sync start"
level=warn t=52.824619ms msg="sync start"
level=warn t=53.2841ms msg="sync start"
level=warn t=53.858961ms msg="sync start"
level=warn t=54.098945ms msg="updateContacts: setting key " index-address:\x00\x00;j'\xbcζ\xa4-b\xa3\xa8\xd0*o\rse2\x15w\x1d\xe2C\xa6:\xc0H\xa1\x8bY\xda)\x00\x00\xa3\xd3\xcd\t\x9fs^V\x15\xa2T\x13x\x0f`\xd9t\xa6\x13\xb4\x89\x0f\xa1\x867ct\xdf\xf8\xd16=" to idxRelValueFollowing"
level=warn t=148.684496ms msg="sync done"
level=warn t=148.790205ms msg="sync done"
level=warn t=148.811296ms msg="sync done"
level=warn t=148.745787ms msg="sync done"
level=warn t=153.454082ms msg="sync done"
level=warn t=153.509299ms msg="waiting for sync"
level=warn t=153.483069ms msg="sync done"
level=warn t=154.659425ms msg="sync done"
level=warn t=154.702457ms msg="sync done"
level=warn t=154.725228ms msg="done waiting for sync"
t=154.743756ms event=info msg="building new graph"
t=154.899552ms event=info msg="processing message"
t=154.925769ms event=info msg="adding node from" nFrom=<@O2on.ed25519>
t=154.994412ms event=info msg="adding node to" nTo=<@o9PN.ed25519>
t=155.022558ms event=info msg="setting edge weight"
t=155.033714ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer bob in graph lookup table (len:2)
level=warn t=155.388835ms msg="waiting for sync"
level=warn t=155.407272ms msg="done waiting for sync"
t=155.415842ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/simple/badger
                Messages:       assertion #1 failed
level=warn t=194.454939ms msg="waiting for sync"
level=warn t=194.49632ms msg="done waiting for sync"
t=194.512702ms event=info msg="using cached graph"
level=warn t=194.554178ms msg="waiting for sync"
level=warn t=194.562761ms msg="done waiting for sync"
t=194.570103ms event=info msg="using cached graph"
level=warn t=194.579564ms msg="waiting for sync"
level=warn t=194.585898ms msg="done waiting for sync"
t=194.592682ms event=info msg="using cached graph"
level=warn t=194.603181ms msg="waiting for sync"
level=warn t=194.609334ms msg="done waiting for sync"
t=194.616576ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow bob
                Test:           TestPeople/simple/badger
                Messages:       assertion #5 failed
level=warn t=224.158046ms msg="waiting for sync"
level=warn t=224.214746ms msg="done waiting for sync"
t=224.225739ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

=== RUN   TestPeople/unfollow/badger
level=warn t=26.107666ms msg="sync start"
level=warn t=26.140844ms msg="sync start"
level=warn t=26.150445ms msg="sync start"
level=warn t=26.157121ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=29.426998ms msg="sync start"
level=warn t=29.548858ms msg="sync start"
level=warn t=29.705873ms msg="sync start"
level=warn t=30.480355ms msg="sync start"
level=warn t=34.00856ms msg="sync start"
level=warn t=34.10459ms msg="sync start"
level=warn t=34.213036ms msg="sync start"
level=warn t=34.337706ms msg="sync start"
level=warn t=34.385996ms msg="sync start"
level=warn t=34.424905ms msg="updateContacts: setting key " index-address:\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=126.437367ms msg="sync done"
level=warn t=126.502252ms msg="sync done"
level=warn t=126.518289ms msg="sync done"
level=warn t=126.53079ms msg="sync done"
level=warn t=129.879655ms msg="sync done"
level=warn t=129.94489ms msg="sync done"
level=warn t=129.982466ms msg="sync done"
level=warn t=134.189762ms msg="sync done"
level=warn t=134.222211ms msg="sync done"
level=warn t=134.235485ms msg="sync done"
level=warn t=134.258712ms msg="sync done"
level=warn t=135.384107ms msg="waiting for sync"
level=warn t=135.405397ms msg="sync done"
level=warn t=135.421584ms msg="sync done"
level=warn t=135.433973ms msg="done waiting for sync"
t=135.443006ms event=info msg="building new graph"
t=135.478425ms event=info msg="processing message"
t=135.549769ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=135.616772ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=135.661806ms event=info msg="setting edge weight"
t=135.681444ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:2)
level=warn t=135.932656ms msg="waiting for sync"
level=warn t=135.942365ms msg="done waiting for sync"
t=135.94822ms event=info msg="using cached graph"
level=warn t=135.958432ms msg="waiting for sync"
level=warn t=135.96325ms msg="done waiting for sync"
t=136.024206ms event=info msg="using cached graph"
level=warn t=136.059217ms msg="waiting for sync"
level=warn t=136.072658ms msg="done waiting for sync"
t=136.078646ms event=info msg="using cached graph"
level=warn t=136.140937ms msg="waiting for sync"
level=warn t=136.160744ms msg="done waiting for sync"
t=136.167427ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow claire
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #4 failed
level=warn t=171.679888ms msg="waiting for sync"
level=warn t=171.7182ms msg="done waiting for sync"
t=171.72777ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

So it would appear that for some reason some messages are being processed but not added to the indexes.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

Logging every return path from the index functions:

=== RUN   TestPeople/simple/badger
level=warn t=30.790986ms msg="sync start"
level=warn t=30.967536ms msg="sync start"
level=warn t=30.981188ms msg="sync start"
level=warn t=30.987801ms msg="sync start"
    people_test.go:65: created(0) alice as @O2onvM62pC1io6jQKm8Nc2UyFXcd4kOmOsBIoYtZ2ik=.ed25519 (algo:ed25519)
    people_test.go:65: created(1) bob as @BoaSQjNgS+1FWhgV6n4vLjyd4jG9NvyH7iX7WqDnFsE=.ed25519 (algo:ed25519)
    people_test.go:65: created(2) claire as @o9PNCZ9zXlYVolQTeA9g2XSmE7SJD6GGN2N0Pd/40TY=.ed25519 (algo:ed25519)
level=warn t=34.973023ms msg="sync start"
level=warn t=35.003992ms msg="updateMetafeeds: skipping - invalid"
level=warn t=35.40824ms msg="sync start"
level=warn t=35.466808ms msg="updateMetafeeds: skipping - invalid"
level=warn t=35.594605ms msg="sync start"
level=warn t=35.686044ms msg="updateContacts: setting key " index-address:\x00\x00;j'\xbcζ\xa4-b\xa3\xa8\xd0*o\rse2\x15w\x1d\xe2C\xa6:\xc0H\xa1\x8bY\xda)\x00\x00\xa3\xd3\xcd\t\x9fs^V\x15\xa2T\x13x\x0f`\xd9t\xa6\x13\xb4\x89\x0f\xa1\x867ct\xdf\xf8\xd16=" to idxRelValueFollowing"
level=warn t=35.857099ms msg="sync start"
level=warn t=35.989124ms msg="updateAnnouncement: skipping invalid"
level=warn t=131.205828ms msg="sync done"
level=warn t=131.303842ms msg="sync done"
level=warn t=131.315235ms msg="sync done"
level=warn t=131.412778ms msg="sync done"
level=warn t=135.130832ms msg="sync done"
level=warn t=136.261342ms msg="waiting for sync"
level=warn t=136.298014ms msg="sync done"
level=warn t=136.377216ms msg="sync done"
level=warn t=136.481971ms msg="sync done"
level=warn t=136.613145ms msg="done waiting for sync"
t=136.670382ms event=info msg="building new graph"
t=136.74311ms event=info msg="processing message"
t=136.801691ms event=info msg="adding node from" nFrom=<@O2on.ed25519>
t=136.865364ms event=info msg="adding node to" nTo=<@o9PN.ed25519>
t=136.887671ms event=info msg="setting edge weight"
t=136.914186ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer bob in graph lookup table (len:2)
level=warn t=137.165157ms msg="waiting for sync"
level=warn t=137.18656ms msg="done waiting for sync"
t=137.210378ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/simple/badger
                Messages:       assertion #1 failed
level=warn t=187.977479ms msg="waiting for sync"
level=warn t=188.031348ms msg="done waiting for sync"
t=188.042381ms event=info msg="using cached graph"
level=warn t=188.072162ms msg="waiting for sync"
level=warn t=188.093029ms msg="done waiting for sync"
t=188.106395ms event=info msg="using cached graph"
level=warn t=188.125053ms msg="waiting for sync"
level=warn t=188.134518ms msg="done waiting for sync"
t=188.146108ms event=info msg="using cached graph"
level=warn t=188.163885ms msg="waiting for sync"
level=warn t=188.174237ms msg="done waiting for sync"
t=188.255054ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow bob
                Test:           TestPeople/simple/badger
                Messages:       assertion #5 failed
level=warn t=216.777899ms msg="waiting for sync"
level=warn t=216.81183ms msg="done waiting for sync"
t=216.82265ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

=== RUN   TestPeople/unfollow/badger
level=warn t=40.05491ms msg="sync start"
level=warn t=40.107965ms msg="sync start"
level=warn t=40.122171ms msg="sync start"
level=warn t=40.132219ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=55.748592ms msg="sync start"
level=warn t=55.790942ms msg="updateMetafeeds: skipping - invalid"
level=warn t=56.083256ms msg="sync start"
level=warn t=56.114582ms msg="updateMetafeeds: skipping - invalid"
level=warn t=56.352928ms msg="sync start"
level=warn t=56.381801ms msg="updateMetafeeds: skipping - invalid"
level=warn t=56.965713ms msg="sync start"
level=warn t=57.177452ms msg="updateContacts: setting key " index-address:\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=57.498612ms msg="sync start"
level=warn t=57.772572ms msg="updateAnnouncement: skipping invalid"
level=warn t=58.170603ms msg="sync start"
level=warn t=58.200153ms msg="updateMetafeeds: skipping - invalid"
level=warn t=140.931272ms msg="sync done"
level=warn t=141.011741ms msg="sync done"
level=warn t=141.032929ms msg="sync done"
level=warn t=141.049355ms msg="sync done"
level=warn t=156.085515ms msg="sync done"
level=warn t=156.176987ms msg="sync done"
level=warn t=157.373761ms msg="sync done"
level=warn t=158.58132ms msg="sync done"
level=warn t=158.632151ms msg="sync done"
level=warn t=158.653836ms msg="waiting for sync"
level=warn t=158.661729ms msg="sync done"
level=warn t=158.677237ms msg="done waiting for sync"
t=158.688883ms event=info msg="building new graph"
t=158.728496ms event=info msg="processing message"
t=158.738501ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=158.771797ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=158.79593ms event=info msg="setting edge weight"
t=158.844116ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:2)
level=warn t=159.04945ms msg="waiting for sync"
level=warn t=159.060283ms msg="done waiting for sync"
t=159.069007ms event=info msg="using cached graph"
level=warn t=159.082912ms msg="waiting for sync"
level=warn t=159.08976ms msg="done waiting for sync"
t=159.097362ms event=info msg="using cached graph"
level=warn t=159.10945ms msg="waiting for sync"
level=warn t=159.131616ms msg="done waiting for sync"
t=159.150768ms event=info msg="using cached graph"
level=warn t=159.210773ms msg="waiting for sync"
level=warn t=159.235215ms msg="done waiting for sync"
t=159.243668ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow claire
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #4 failed
level=warn t=221.731306ms msg="waiting for sync"
level=warn t=221.773772ms msg="done waiting for sync"
t=221.858233ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

=== RUN   TestPeople/simple/badger
level=warn t=45.863556ms msg="sync start"
level=warn t=45.923762ms msg="sync start"
level=warn t=45.951365ms msg="sync start"
level=warn t=45.964361ms msg="sync start"
    people_test.go:65: created(0) alice as @O2onvM62pC1io6jQKm8Nc2UyFXcd4kOmOsBIoYtZ2ik=.ed25519 (algo:ed25519)
    people_test.go:65: created(1) bob as @BoaSQjNgS+1FWhgV6n4vLjyd4jG9NvyH7iX7WqDnFsE=.ed25519 (algo:ed25519)
    people_test.go:65: created(2) claire as @o9PNCZ9zXlYVolQTeA9g2XSmE7SJD6GGN2N0Pd/40TY=.ed25519 (algo:ed25519)
level=warn t=52.10046ms msg="sync start"
level=warn t=52.142172ms msg="updateMetafeeds: skipping - invalid"
level=warn t=52.369728ms msg="sync start"
level=warn t=52.407709ms msg="updateMetafeeds: skipping - invalid"
level=warn t=146.092782ms msg="sync done"
level=warn t=146.313157ms msg="sync done"
level=warn t=146.35237ms msg="sync done"
level=warn t=146.173979ms msg="sync done"
level=warn t=151.94843ms msg="waiting for sync"
level=warn t=153.245954ms msg="sync done"
level=warn t=153.333152ms msg="sync done"
level=warn t=153.371879ms msg="done waiting for sync"
t=153.42376ms event=info msg="building new graph"
t=153.491283ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/simple/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
level=warn t=154.029796ms msg="waiting for sync"
level=warn t=154.064946ms msg="done waiting for sync"
t=154.087651ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/simple/badger
                Messages:       assertion #1 failed
level=warn t=168.217745ms msg="waiting for sync"
level=warn t=168.238965ms msg="done waiting for sync"
t=168.245039ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/simple/badger
                Messages:       assertion #2 failed
level=warn t=182.957328ms msg="waiting for sync"
level=warn t=182.979786ms msg="done waiting for sync"
t=182.987472ms event=info msg="using cached graph"
level=warn t=183.001226ms msg="waiting for sync"
level=warn t=183.004862ms msg="done waiting for sync"
t=183.020123ms event=info msg="using cached graph"
level=warn t=183.027919ms msg="waiting for sync"
level=warn t=183.031245ms msg="done waiting for sync"
t=183.034644ms event=info msg="using cached graph"
level=warn t=183.040477ms msg="authbypass - trust on first use"
level=warn t=183.045559ms msg="waiting for sync"
level=warn t=183.048784ms msg="done waiting for sync"
t=183.052529ms event=info msg="using cached graph"
level=warn t=183.057348ms msg="authbypass - trust on first use"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: host(bob) accepted remote(alice) (dist:0)
                Test:           TestPeople/simple/badger
                Messages:       assertion #6 failed
    builder_test.go:130: closed scenary

=== RUN   TestPeople/unfollow/badger
level=warn t=44.516379ms msg="sync start"
level=warn t=44.57128ms msg="sync start"
level=warn t=44.58569ms msg="sync start"
level=warn t=44.595472ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=50.829236ms msg="sync start"
level=warn t=50.888581ms msg="updateMetafeeds: skipping - invalid"
level=warn t=51.051747ms msg="sync start"
level=warn t=51.08054ms msg="updateMetafeeds: skipping - invalid"
level=warn t=51.187903ms msg="sync start"
level=warn t=51.208231ms msg="updateMetafeeds: skipping - invalid"
level=warn t=51.288407ms msg="sync start"
level=warn t=51.307579ms msg="updateMetafeeds: skipping - invalid"
level=warn t=144.646227ms msg="sync done"
level=warn t=144.72866ms msg="sync done"
level=warn t=144.749243ms msg="sync done"
level=warn t=144.746042ms msg="sync done"
level=warn t=150.785482ms msg="waiting for sync"
level=warn t=152.01426ms msg="sync done"
level=warn t=152.073808ms msg="sync done"
level=warn t=152.094339ms msg="sync done"
level=warn t=152.09526ms msg="sync done"
level=warn t=152.342261ms msg="done waiting for sync"
t=152.379358ms event=info msg="building new graph"
t=152.565547ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer claire in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:0)
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer bob in graph lookup table (len:0)
level=warn t=153.669373ms msg="waiting for sync"
level=warn t=153.754751ms msg="done waiting for sync"
t=153.864155ms event=info msg="using cached graph"
level=warn t=153.899099ms msg="waiting for sync"
level=warn t=153.908496ms msg="done waiting for sync"
t=153.916358ms event=info msg="using cached graph"
level=warn t=153.927931ms msg="waiting for sync"
level=warn t=154.019954ms msg="done waiting for sync"
t=154.031004ms event=info msg="using cached graph"
level=warn t=154.038833ms msg="authbypass - trust on first use"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: host(alice) accepted remote(bob) (dist:0)
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #3 failed
level=warn t=173.097054ms msg="waiting for sync"
level=warn t=173.140937ms msg="done waiting for sync"
t=173.152364ms event=info msg="using cached graph"
level=warn t=173.160473ms msg="authbypass - trust on first use"
level=warn t=173.176996ms msg="waiting for sync"
level=warn t=173.295647ms msg="done waiting for sync"
t=173.328847ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                follows assert failed - wanted true
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #5 failed
    builder_test.go:130: closed scenary

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

So, the times that updateMetafeeds is skipping are quite interesting:

=== RUN   TestPeople/unfollow/badger
level=warn t=35.828305ms msg="sync start"
level=warn t=35.942877ms msg="sync start"
level=warn t=36.107718ms msg="sync start"
level=warn t=36.148342ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
level=warn t=42.126279ms msg="sync start"
level=warn t=42.175366ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=42.497405ms msg="sync start"
level=warn t=42.534942ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=42.796484ms msg="sync start"
level=warn t=42.833937ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=43.960146ms msg="sync start"
level=warn t=44.030022ms msg="updateAnnouncement: skipping invalid"
level=warn t=44.471512ms msg="sync start"
level=warn t=44.5067ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=44.778927ms msg="sync start"
level=warn t=44.994421ms msg="updateContacts: setting key " index-address:\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=136.606724ms msg="sync done"
level=warn t=136.67878ms msg="sync done"
level=warn t=136.700405ms msg="sync done"
level=warn t=136.716571ms msg="sync done"
level=warn t=142.561708ms msg="sync done"
level=warn t=142.631614ms msg="sync done"
level=warn t=143.805568ms msg="sync done"
level=warn t=145.009924ms msg="sync done"
level=warn t=145.062474ms msg="sync done"
level=warn t=146.274518ms msg="waiting for sync"
level=warn t=146.312972ms msg="sync done"
level=warn t=146.338699ms msg="done waiting for sync"
t=146.365419ms event=info msg="building new graph"
t=146.413559ms event=info msg="processing message"
t=146.433271ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=146.454042ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=146.465171ms event=info msg="setting edge weight"
t=146.485101ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:2)
level=warn t=146.801344ms msg="waiting for sync"
level=warn t=146.815109ms msg="done waiting for sync"
t=146.823352ms event=info msg="using cached graph"
level=warn t=146.836767ms msg="waiting for sync"
level=warn t=146.843816ms msg="done waiting for sync"
t=146.852002ms event=info msg="using cached graph"
level=warn t=146.864176ms msg="waiting for sync"
level=warn t=146.870647ms msg="done waiting for sync"
t=146.878479ms event=info msg="using cached graph"
level=warn t=146.906855ms msg="waiting for sync"
level=warn t=146.922916ms msg="done waiting for sync"
t=146.931013ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow claire
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #4 failed
level=warn t=187.763506ms msg="waiting for sync"
level=warn t=187.800059ms msg="done waiting for sync"
t=187.811278ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

@decentral1se Any idea what could be causing this?

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

I should note that that's coming from here:

go-ssb/graph/builder_indexing.go

Line 184 in 55f4894

if msg.Author().Algo() != refs.RefAlgoFeedBendyButt {

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

Added logging to the test helper:

=== RUN   TestPeople/unfollow/badger
level=warn t=34.056949ms msg="sync start"
level=warn t=34.124317ms msg="sync start"
level=warn t=34.140926ms msg="sync start"
level=warn t=34.150944ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
2023/02/02 14:20:27 publisher: follow
2023/02/02 14:20:27 publisher: unfollow
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
2023/02/02 14:20:27 publisher: follow
2023/02/02 14:20:27 publisher: follow
level=warn t=39.560741ms msg="sync start"
level=warn t=39.706792ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=40.040482ms msg="sync start"
level=warn t=40.162232ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=40.422857ms msg="sync start"
level=warn t=40.552179ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=40.923903ms msg="sync start"
level=warn t=41.058264ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=41.345062ms msg="sync start"
level=warn t=41.55313ms msg="updateAnnouncement: skipping invalid"
level=warn t=41.780205ms msg="sync start"
level=warn t=41.925249ms msg="updateAnnouncement: skipping invalid"
level=warn t=42.246338ms msg="sync start"
level=warn t=42.440061ms msg="updateContacts: setting key " index-address:\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=135.133407ms msg="sync done"
level=warn t=135.295346ms msg="sync done"
level=warn t=135.450305ms msg="sync done"
level=warn t=135.211139ms msg="sync done"
level=warn t=140.326541ms msg="sync done"
level=warn t=140.40273ms msg="sync done"
level=warn t=141.675678ms msg="sync done"
level=warn t=141.738049ms msg="sync done"
level=warn t=141.768812ms msg="waiting for sync"
level=warn t=141.7786ms msg="sync done"
level=warn t=142.930618ms msg="sync done"
level=warn t=142.982301ms msg="sync done"
level=warn t=143.001656ms msg="done waiting for sync"
t=143.018002ms event=info msg="building new graph"
t=143.067242ms event=info msg="processing message"
t=143.16694ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=143.269382ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=143.287546ms event=info msg="setting edge weight"
t=143.330307ms event=info msg="processing message"
    people_test.go:277:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:277
                Error:          Should be true
                Test:           TestPeople/unfollow/badger
                Messages:       did not find peer alice in graph lookup table (len:2)
level=warn t=143.74051ms msg="waiting for sync"
level=warn t=143.767108ms msg="done waiting for sync"
t=143.776138ms event=info msg="using cached graph"
level=warn t=143.787678ms msg="waiting for sync"
level=warn t=143.793976ms msg="done waiting for sync"
t=143.801208ms event=info msg="using cached graph"
level=warn t=143.813652ms msg="waiting for sync"
level=warn t=143.874469ms msg="done waiting for sync"
t=143.90467ms event=info msg="using cached graph"
level=warn t=143.977444ms msg="waiting for sync"
level=warn t=144.070966ms msg="done waiting for sync"
t=144.094447ms event=info msg="using cached graph"
    people_test.go:286:
                Error Trace:    /home/go-ssb/go-ssb/graph/people_test.go:286
                Error:          Received unexpected error:
                                auth assert: alice didn't allow claire
                Test:           TestPeople/unfollow/badger
                Messages:       assertion #4 failed
level=warn t=181.839402ms msg="waiting for sync"
level=warn t=181.890446ms msg="done waiting for sync"
t=181.903581ms event=info msg="using cached graph"
    builder_test.go:130: closed scenary

So the follow/unfollow information is getting published, but not reliably showing up in the indexes. Looking at other successful tests, like this:

=== RUN   TestPeople/unfollow/badger
level=warn t=28.293253ms msg="sync start"
level=warn t=28.427361ms msg="sync start"
level=warn t=28.491089ms msg="sync start"
level=warn t=28.559245ms msg="sync start"
    people_test.go:65: created(3) alice as @mTABbvnx4tu2VAm3SpLCBOcyeklDySXdaQA3wMlRomw=.ed25519 (algo:ed25519)
    people_test.go:65: created(4) bob as @rNM8Fp8TcXo7XXoFE3uFO/B7c+QdN+JdcPEc45VQlaI=.ed25519 (algo:ed25519)
2023/02/02 14:20:30 publisher: follow
level=warn t=32.161043ms msg="sync start"
level=warn t=32.325073ms msg="updateContacts: setting key " index-address:\x00\x00\x990\x01n\xf9\xf1\xe2۶T\t\xb7J\x92\xc2\x04\xe72zIC\xc9%\xddi\x007\xc0\xc9Q\xa2l\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=32.685947ms msg="sync start"
level=warn t=32.777767ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=32.909228ms msg="sync start"
level=warn t=33.06599ms msg="updateAnnouncement: skipping invalid"
2023/02/02 14:20:30 publisher: unfollow
level=warn t=35.667249ms msg="sync start"
level=warn t=35.861937ms msg="updateContacts: setting key " index-address:\x00\x00\x990\x01n\xf9\xf1\xe2۶T\t\xb7J\x92\xc2\x04\xe72zIC\xc9%\xddi\x007\xc0\xc9Q\xa2l\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueNone"
level=warn t=36.082079ms msg="sync start"
level=warn t=36.160986ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=36.271421ms msg="sync start"
level=warn t=36.375775ms msg="updateAnnouncement: skipping invalid"
    people_test.go:65: created(5) claire as @WGW2y4cA6nsp3h5syPJJIX0WwJjWhsngfFpVuY78YG8=.ed25519 (algo:ed25519)
2023/02/02 14:20:30 publisher: follow
level=warn t=38.237531ms msg="sync start"
level=warn t=38.384006ms msg="updateContacts: setting key " index-address:\x00\x00\x990\x01n\xf9\xf1\xe2۶T\t\xb7J\x92\xc2\x04\xe72zIC\xc9%\xddi\x007\xc0\xc9Q\xa2l\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o=" to idxRelValueFollowing"
level=warn t=38.573474ms msg="sync start"
level=warn t=38.653715ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=38.846925ms msg="sync start"
level=warn t=39.080328ms msg="updateAnnouncement: skipping invalid"
2023/02/02 14:20:30 publisher: follow
level=warn t=40.728058ms msg="sync start"
level=warn t=40.805238ms msg="updateContacts: setting key " index-address:\x00\x00Xe\xb6ˇ\x00\xea{)\xde\x1el\xc8\xf2I!}\x16\xc0\x98ֆ\xc9\xe0|ZU\xb9\x8e\xfc`o\x00\x00\xac\xd3<\x16\x9f\x13qz;]z\x05\x13{\x85;\xf0{s\xe4\x1d7\xe2]p\xf1\x1c\xe3\x95P\x95\xa2=" to idxRelValueFollowing"
level=warn t=41.116317ms msg="sync start"
level=warn t=41.148318ms msg="updateMetafeeds: skipping - invalid because feed type is not RefAlgoFeedBendyButt but is instead " ed25519=(MISSING)
level=warn t=41.336175ms msg="sync start"
level=warn t=41.491143ms msg="updateAnnouncement: skipping invalid"
level=warn t=129.400962ms msg="sync done"
level=warn t=129.481338ms msg="sync done"
level=warn t=129.501545ms msg="sync done"
level=warn t=129.536065ms msg="sync done"
level=warn t=132.818034ms msg="sync done"
level=warn t=132.903173ms msg="sync done"
level=warn t=134.081128ms msg="sync done"
level=warn t=136.463944ms msg="sync done"
level=warn t=136.526364ms msg="sync done"
level=warn t=136.546892ms msg="sync done"
level=warn t=138.93204ms msg="sync done"
level=warn t=139.016535ms msg="sync done"
level=warn t=140.207918ms msg="sync done"
level=warn t=141.426461ms msg="sync done"
level=warn t=141.486343ms msg="sync done"
level=warn t=141.529787ms msg="sync done"
level=warn t=142.721474ms msg="waiting for sync"
level=warn t=142.757696ms msg="done waiting for sync"
t=142.771045ms event=info msg="building new graph"
t=142.818232ms event=info msg="processing message"
t=142.828066ms event=info msg="adding node from" nFrom=<@WGW2.ed25519>
t=142.854044ms event=info msg="adding node to" nTo=<@rNM8.ed25519>
t=142.887907ms event=info msg="setting edge weight"

I almost wonder if the problem is that with the failed ones the messages are published before any indexing takes place whereas the successful tests seem to be where each message is indexes immediately after it's published. So it may be an issue with the not-live vs. live message pumps.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023 •
edited
Loading

Now wait just a doggone minute...it's not actually doing a non-live query first:

https://github.com/ssbc/go-ssb/blob/55f48949535cc3e42ec8cbf20b75e1cb003a7ab9/graph/builder_test.go#L316-335

serveLog is always called with live==true.

I think we may have our explanation.

@KyleMaas
Copy link
Contributor Author

KyleMaas commented Feb 2, 2023

Well, made it to 300 runs without any errors or failures. Going to do some more tweaking but finally making progress.

@KyleMaas KyleMaas mentioned this issue Feb 2, 2023
Merged
@github-project-automation github-project-automation bot moved this from Prioritised to Done in 🚧 go-ssb maintenance 🚧 Feb 5, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
testing
Projects
🚧 go-ssb maintenance 🚧
Status: Done
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix TestPeople KyleMaas/go-ssb
2 participants
@decentral1se @KyleMaas