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

TestNullFeed is flaky #268

Open
KyleMaas opened this issue Dec 20, 2022 · 10 comments
Open

TestNullFeed is flaky #268

KyleMaas opened this issue Dec 20, 2022 · 10 comments
Labels
testing

Comments

@KyleMaas
Copy link
Contributor

Looks like another race condition:

2022/12/20 21:37:35 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestNullFeed
2022/12/20 21:37:35 saved identity @feg0/jnGLq3efpsmjJKdl57ciUBp9MfTT0hP4MhKU3w=.ed25519 to testrun/TestNullFeed/main/secrets/arny
2022/12/20 21:37:35 saved identity ssb:feed/gabbygrove-v1/FjfVXOAz0UIHWiCye0CusyiYihBQio8dMshL6pR12kE= to testrun/TestNullFeed/main/secrets/bert
2022/12/20 21:37:35 saved identity @1xUG2rp8JA3kub2RIKpxbU8wx9zOBGjfCYaHPdgebU0=.ed25519 to testrun/TestNullFeed/main/secret
level=debug t=723.3066ms bot=main TODO="found gg feed, using that. overhaul shs1 to support more payload in the handshake"
level=debug t=732.885047ms bot=main unit=gossip fr=<@1xUG.ed25519> event=gossiptx n=1 starting=0
level=debug t=744.308068ms bot=bert plugin=gossip event=gossiprx fr=<@1xUG.ed25519> starting=0 received=1 took=17.831716ms
level=debug t=744.624491ms bot=main plugin=gossip event=gossiprx fr=<@FjfV.gabbygrove-v1> starting=0 received=16 took=18.798812ms
level=warn t=744.8951ms bot=main plugin=gossip event="skipped updating of stored feed" err="ValidateNext(ssb:feed/gabbygrove-v1/FjfVXOAz0UIHWiCye0CusyiYihBQio8dMshL6pR12kE=:1): previous compare failed expected:ssb:message/gabbygrove-v1/ioTtRf8p7vLBpULTfFxGsBI-wi9B_blb8xWahkv211o= incoming:ssb:message/gabbygrove-v1/aynC_rxb_EEWtFwJl-5jD9tUC1q1rASsoDGt0nza300=" fr=<@FjfV.gabbygrove-v1>
level=debug t=860.414728ms bot=bert unit=gossip fr=<@FjfV.gabbygrove-v1> event=gossiptx n=1001 starting=0
level=debug t=3.731049056s bot=main event=update-replicate feed-want-count=1 hops=2 took=789.593µs
level=debug t=3.745702595s bot=bert event=update-replicate feed-want-count=1 hops=0 took=370.818µs
    null_feed_test.go:179: sync timeout
level=warn t=25.724704864s bot=bert unit=gossip event="live qry on rxlog exited"
level=warn t=25.724851684s bot=main unit=gossip event="live qry on rxlog exited"
level=debug t=25.7249006s bot=main event="network listen loop exited"
level=debug t=25.725023983s bot=bert event="network listen loop exited"
t=25.726594805s bot=bert event=warning msg="still open connections" count=1
level=debug t=25.726686018s bot=bert event="sbot closing" msg="connections closed"
level=debug t=25.726714874s bot=bert event="sbot closing" msg="waited for indexes to close"
level=info t=25.743689234s bot=bert event="sbot closing" msg="closers closed"
level=debug t=25.743747979s bot=main event="sbot closing" msg="connections closed"
level=debug t=25.743764113s bot=main event="sbot closing" msg="waited for indexes to close"
level=info t=25.754467256s bot=main event="sbot closing" msg="closers closed"
--- FAIL: TestNullFeed (25.75s)
FAIL
FAIL	github.com/ssbc/go-ssb/sbot	25.782s
FAIL
@KyleMaas
Copy link
Contributor Author

Not entirely sure what the purpose of this test is. It could use a bit more documentation as to what it's testing and how it's testing it.

@KyleMaas
Copy link
Contributor Author

Okay, so I think the problem is actually that the messages are not being fully deleted from mainbot before it attempts to re-replicate from bertbot, which then throws off the validation because there is still a previous message and at that point it has detected a forked feed, which is AFAICT what this is creating. It's actually a pretty clever test if you step through it.

So the failure does appear to be catching a legitimate problem - either NullFeed() is not synchronous, it is not working right, or messages are still being processed and published to the receive log after the NullFeed() call.

@KyleMaas
Copy link
Contributor Author

Hmmm...another possibility: it's replicating the messages out of order.

So far, I don't see how it could be any of my previous hypotheses. NullFeed() must be synchronous, because that is checked by sequence number. Messages can't be being processed after NullFeed(), since that is also checked by sequence number. And the feed is being properly nulled, because that is also checked. All of those things are checked before bertbot is started. So...the thing this test is supposed to be checking does appear to be working. The failure is happening when this pushes the capability outside of NullFeed(). To a certain extent, it means the test is wrong - it's testing too far outside the scope of what it needs to be testing. But it also means that once we figure out where the failure is, this same test should be repeated but as a separate appropriately-named test.

@KyleMaas KyleMaas mentioned this issue Dec 20, 2022
Draft
@KyleMaas
Copy link
Contributor Author

Interesting...I added a few more checks, and this one failed in one of the runs (which I terminated because I thought I had a bug in my changes, but subsequent re-runs did not have this FAIL):

2022/12/20 22:39:37 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestNullFeed
2022/12/20 22:39:37 saved identity @hkxMuKAC1m6K2Dsf7cqAsoiinJiZvjW4swjXjI1haM8=.ed25519 to testrun/TestNullFeed/main/secrets/arny
2022/12/20 22:39:37 saved identity ssb:feed/gabbygrove-v1/EBw-bfAPfD9YA9K6SRUIWgknIPBtPfGd1tg174EHUII= to testrun/TestNullFeed/main/secrets/bert
2022/12/20 22:39:37 saved identity @U+rJpvvXpPAa3C51QdSFGyuGAtc2z4v1yoJluG1s8iU=.ed25519 to testrun/TestNullFeed/main/secret
    null_feed_test.go:97: 
        	Error Trace:	/home/go-ssb/go-ssb/sbot/null_feed_test.go:97
        	            				/home/go-ssb/go-ssb/sbot/null_feed_test.go:116
        	            				/home/go-ssb/go-ssb/sbot/null_feed_test.go:123
        	Error:      	Not equal: 
        	            	expected: int(1)
        	            	actual  : int64(-1)
        	Test:       	TestNullFeed
level=debug t=3.02020738s bot=main event=update-replicate feed-want-count=0 hops=2 took=239.074µs
^C
FAIL	github.com/ssbc/go-ssb/sbot	8.128s

Oddly enough, this is a different failure. This would be at the arny check here:

https://github.com/KyleMaas/go-ssb/blob/9a03418d17f72f0b4e77e009574bb1a2676f5965/sbot/null_feed_test.go#L123

About the only way I could think of for that to happen is if the act of publishing is not synchronous. Or the disk write isn't, which is entirely possible since PublishAs reopens the log for every message it writes.

I think. Still getting acquainted with the codebase.

@KyleMaas
Copy link
Contributor Author

Huh. Yet another different error from this test:

https://github.com/ssbc/go-ssb/actions/runs/3744726663/jobs/6358410184#step:9:406

@KyleMaas
Copy link
Contributor Author

Whew, that last one's a doozy. If I read that right, since that failed, it means that indexing was still happening after the messages were nulled from the main log. Without any kind of index locking or any way to know if the indexes are up-to-date (see #251), that means that the indexes now need to be able to deal with messages being fed to them which have already been deleted.

@KyleMaas KyleMaas mentioned this issue Dec 20, 2022
Open
@KyleMaas
Copy link
Contributor Author 

2022/12/21 01:42:19 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestNullFeed
2022/12/21 01:42:19 saved identity @+ap3yHh6AxiyBuw+uaDwto1feAhb2JIvWFK1IZMQcfw=.ed25519 to testrun/TestNullFeed/main/secrets/arny
2022/12/21 01:42:19 saved identity ssb:feed/gabbygrove-v1/ZyXUJAALXglh2REf3nYxZwoNdfhKs0qJkS8wEPANgqA= to testrun/TestNullFeed/main/secrets/bert
2022/12/21 01:42:19 saved identity @4hQ/pyb9iE/UDlBNWLEJ39rT8+0uv15pII/M+4oe4zA=.ed25519 to testrun/TestNullFeed/main/secret
level=debug t=767.450881ms bot=main TODO="found gg feed, using that. overhaul shs1 to support more payload in the handshake"
level=debug t=770.876515ms bot=main unit=gossip fr=<@4hQ/.ed25519> event=gossiptx n=1 starting=0
level=debug t=772.777349ms bot=bert plugin=gossip event=gossiprx fr=<@4hQ/.ed25519> starting=0 received=1 took=2.724176ms
level=debug t=776.872841ms bot=main plugin=gossip event=gossiprx fr=<@ZyXU.gabbygrove-v1> starting=0 received=4 took=4.903573ms
level=warn t=776.939402ms bot=main plugin=gossip event="skipped updating of stored feed" err="ValidateNext(ssb:feed/gabbygrove-v1/ZyXUJAALXglh2REf3nYxZwoNdfhKs0qJkS8wEPANgqA=:1): previous compare failed expected:ssb:message/gabbygrove-v1/-hGJrCuS6NQuJFm-EajlCYtbc8yEcq8blhiFBKEM3Wc= incoming:ssb:message/gabbygrove-v1/_i-aJW-g9GX55ZH2wzZhWSOO-axVvg_mV9Zg-r7OfzY=" fr=<@ZyXU.gabbygrove-v1>
level=debug t=895.193437ms bot=bert unit=gossip fr=<@ZyXU.gabbygrove-v1> event=gossiptx n=1001 starting=0
level=debug t=3.774110668s bot=bert event=update-replicate feed-want-count=1 hops=0 took=397.8µs
level=debug t=3.776326693s bot=main event=update-replicate feed-want-count=1 hops=2 took=1.009133ms
    null_feed_test.go:194: sync timeout
level=warn t=25.76836701s bot=bert unit=gossip event="live qry on rxlog exited"
level=warn t=25.768595513s bot=main unit=gossip event="live qry on rxlog exited"
t=25.769005433s bot=bert event=warning msg="still open connections" count=1
level=debug t=25.769057287s bot=bert event="sbot closing" msg="connections closed"
level=debug t=25.769068587s bot=bert event="sbot closing" msg="waited for indexes to close"
level=debug t=25.76976283s bot=main unit=blobs event=onCall handler=createWants err="muxrpc CallError: Error - muxrpc: session terminated"
level=debug t=25.770332308s bot=main event="network listen loop exited"
level=debug t=25.770532787s bot=bert event="network listen loop exited"
level=info t=25.78609192s bot=bert event="sbot closing" msg="closers closed"
level=debug t=25.786121895s bot=main event="sbot closing" msg="connections closed"
level=debug t=25.786129876s bot=main event="sbot closing" msg="waited for indexes to close"
level=info t=25.799634593s bot=main event="sbot closing" msg="closers closed"
--- FAIL: TestNullFeed (25.80s)
FAIL
FAIL	github.com/ssbc/go-ssb/sbot	25.825s
FAIL

So...it made it through checking that both logs were in a stable state where they should be before replication started. So they both had the correct sequence numbers at that point. So this pretty much had to have happened during the replication step.

@KyleMaas
Copy link
Contributor Author

Now here's an interesting one:

2022/12/21 01:54:21 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestNullFeed
2022/12/21 01:54:21 saved identity @aEw5pHaLco3MxKjEGXKQHn+74ow5Tidtk4aw1OoSM1k=.ed25519 to testrun/TestNullFeed/main/secrets/arny
2022/12/21 01:54:21 saved identity ssb:feed/gabbygrove-v1/KI1gHjzn6GfM7Vf2YHdH6erUaQtzIth5JK-sHb8BiLA= to testrun/TestNullFeed/main/secrets/bert
2022/12/21 01:54:21 saved identity @5vrWDp+XuyPBdu7XYsd0lko1+CrmLoaVTi0c+GYFAu4=.ed25519 to testrun/TestNullFeed/main/secret
    null_feed_test.go:156: 
        	Error Trace:	/home/go-ssb/go-ssb/sbot/null_feed_test.go:156
        	Error:      	Received unexpected error:
        	            	ssb/consistency error: message sequence missmatch for feed @aEw5pHaLco3MxKjEGXKQHn+74ow5Tidtk4aw1OoSM1k=.ed25519 Stored:2 Logical:1
        	Test:       	TestNullFeed
level=debug t=3.048504119s bot=main event=update-replicate feed-want-count=1 hops=2 took=389.75µs
level=debug t=3.049309913s bot=bert event=update-replicate feed-want-count=1 hops=0 took=745.004µs
    leakcheck.go:113: Leaked goroutine: goroutine 10 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00011cf00)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 100 [select]:
        github.com/dgraph-io/ristretto.(*Cache).processItems(0xc000145080)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:452 +0x15e
        created by github.com/dgraph-io/ristretto.NewCache
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:207 +0x696
    leakcheck.go:113: Leaked goroutine: goroutine 101 [select]:
        github.com/dgraph-io/badger/v3.(*DB).monitorCache(0xc00225e480, 0xc0021bc810)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:469 +0x18a
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:311 +0xc8b
    leakcheck.go:113: Leaked goroutine: goroutine 102 [select]:
        github.com/dgraph-io/badger/v3.(*DB).updateSize(0xc00225e480, 0xc0021bc960)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:1171 +0x158
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:331 +0xe8c
    leakcheck.go:113: Leaked goroutine: goroutine 103 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc0022089a0, 0x0, 0xc0021bcb10)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 104 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc0022089a0, 0x1, 0xc0021bcb10)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 105 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc0022089a0, 0x2, 0xc0021bcb10)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 106 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc0022089a0, 0x3, 0xc0021bcb10)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 107 [chan receive]:
        github.com/dgraph-io/badger/v3.(*DB).flushMemtable(0xc00225e480, 0x0?)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:1078 +0xb2
        github.com/dgraph-io/badger/v3.Open.func5()
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:357 +0x25
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:356 +0x107c
    leakcheck.go:113: Leaked goroutine: goroutine 108 [select]:
        github.com/dgraph-io/badger/v3.(*vlogThreshold).listenForValueThresholdUpdate(0xc000162880)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/value.go:1172 +0x11a
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:380 +0x16dc
    leakcheck.go:113: Leaked goroutine: goroutine 109 [select]:
        github.com/dgraph-io/badger/v3.(*DB).doWrites(0xc00225e480, 0xc0021bcbd0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:900 +0x236
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:387 +0x179c
    leakcheck.go:113: Leaked goroutine: goroutine 11 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0024f5c50, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0024f5c50, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc00000e630, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb44539f38?, 0xc00000e7c8?}, {0xff5700, 0xc00000e630})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 110 [chan receive]:
        github.com/dgraph-io/badger/v3.(*valueLog).waitOnGC(0xc00225e678, 0x0?)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/value.go:1079 +0x7d
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:391 +0x185b
    leakcheck.go:113: Leaked goroutine: goroutine 111 [select]:
        github.com/dgraph-io/badger/v3.(*publisher).listenForUpdates(0xc002194660, 0xc0021bcc30)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/publisher.go:73 +0x150
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:395 +0x190a
    leakcheck.go:113: Leaked goroutine: goroutine 112 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000164690)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 113 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000164730)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 114 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc0001647d0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 115 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000164870)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 116 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00796ae60)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 117 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc0000e7440, {0xffc430, 0xc00014fe60}, {0x7fbb44539f38?, 0xc000154930?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb44539f38?, 0xc000154930?}, {0xff5c20, 0xc0000e7440})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 118 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00796af00)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 119 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000164af0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 12 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00011d040)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 120 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc0000e7aa0, {0xffc430, 0xc00014fe60}, {0x7fbb4401b118?, 0xc000171290?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb4401b118?, 0xc000171290?}, {0xff5c20, 0xc0000e7aa0})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 121 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00796afa0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 122 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0000e4ae0, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0000e4ae0, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc0000e29f0, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb44539f38?, 0xc000154a08?}, {0xff5700, 0xc0000e29f0})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 123 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00796b0e0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 124 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0000e4c90, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0000e4c90, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc0000e2b88, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb44539f38?, 0xc000154a98?}, {0xff5700, 0xc0000e2b88})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 125 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00796b2c0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 126 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0000e4de0, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0000e4de0, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc0000e2c90, {0xffc430, 0xc00014fe60})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb44539f38?, 0xc000154b58?}, {0xff5700, 0xc0000e2c90})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 127 [select]:
        github.com/ssbc/go-ssb/sbot.debounce({0xffc430, 0xc00014fe60}, 0xb2d05e00, {0xffa010, 0xc000162680}, 0xc0021da660)
        	/home/go-ssb/go-ssb/sbot/replicate.go:135 +0x16c
        created by github.com/ssbc/go-ssb/sbot.(*Sbot).newGraphReplicator
        	/home/go-ssb/go-ssb/sbot/replicate.go:73 +0x3c5
    leakcheck.go:113: Leaked goroutine: goroutine 128 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc002210300, {0xffc430, 0xc00014fe60}, {0xff93d0?, 0xc002212d10?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0xff93d0?, 0xc002212d10?}, {0xff5c20, 0xc002210300})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc002208f50)
        	/home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:107 +0x168
        created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        	/home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:70 +0x1ea
    leakcheck.go:113: Leaked goroutine: goroutine 129 [select]:
        github.com/ssbc/go-ssb/network.(*Node).Serve(0xc0021e6240, {0xffc0b0?, 0xc00013bb00}, {0x0, 0x0, 0x0})
        	/home/go-ssb/go-ssb/network/new.go:431 +0x76d
        github.com/ssbc/go-ssb/sbot.botServer.Serve.func1()
        	/home/go-ssb/go-ssb/sbot/util_test.go:28 +0x57
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 13 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0024f5d70, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0024f5d70, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc00000f998, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb44539f38?, 0xc00000e858?}, {0xff5700, 0xc00000f998})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 14 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc00011d220)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 143 [IO wait]:
        internal/poll.runtime_pollWait(0x7fbb44d66128, 0x72)
        	/usr/lib/go-1.18/src/runtime/netpoll.go:302 +0x89
        internal/poll.(*pollDesc).wait(0xc0000fe300?, 0x561b18?, 0x0)
        	/usr/lib/go-1.18/src/internal/poll/fd_poll_runtime.go:83 +0x32
        internal/poll.(*pollDesc).waitRead(...)
        	/usr/lib/go-1.18/src/internal/poll/fd_poll_runtime.go:88
        internal/poll.(*FD).Accept(0xc0000fe300)
        	/usr/lib/go-1.18/src/internal/poll/fd_unix.go:614 +0x22c
        net.(*netFD).accept(0xc0000fe300)
        	/usr/lib/go-1.18/src/net/fd_unix.go:172 +0x35
        net.(*TCPListener).accept(0xc0000e2d20)
        	/usr/lib/go-1.18/src/net/tcpsock_posix.go:139 +0x28
        net.(*TCPListener).Accept(0xc0000e2d20)
        	/usr/lib/go-1.18/src/net/tcpsock.go:288 +0x3d
        github.com/ssbc/go-netwrap.(*listener).Accept(0xc00225d8c0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/listener.go:60 +0x3e
        github.com/ssbc/go-ssb/network.(*Node).Serve.func3()
        	/home/go-ssb/go-ssb/network/new.go:414 +0xf1
        created by github.com/ssbc/go-ssb/network.(*Node).Serve
        	/home/go-ssb/go-ssb/network/new.go:405 +0x52a
    leakcheck.go:113: Leaked goroutine: goroutine 15 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*query).livequery(0xc0024f5e90, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:158 +0xe7
        github.com/ssbc/margaret/multilog/roaring.(*query).Next(0xc0024f5e90, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/qry.go:126 +0x328
        github.com/ssbc/go-luigi/mfr.(*srcMap).Next(0xc00000fa70, {0xffc430, 0xc002218720})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/mfr/map.go:58 +0x33
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb44539f38?, 0xc00000e918?}, {0xff5700, 0xc00000fa70})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:60 +0xac
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 16 [select]:
        github.com/ssbc/go-ssb/sbot.debounce({0xffc430, 0xc002218720}, 0xb2d05e00, {0xffa010, 0xc00013bdc0}, 0xc000090f60)
        	/home/go-ssb/go-ssb/sbot/replicate.go:135 +0x16c
        created by github.com/ssbc/go-ssb/sbot.(*Sbot).newGraphReplicator
        	/home/go-ssb/go-ssb/sbot/replicate.go:73 +0x3c5
    leakcheck.go:113: Leaked goroutine: goroutine 23 [select]:
        github.com/ssbc/go-ssb/internal/ctxutils.WithError.func2()
        	/home/go-ssb/go-ssb/internal/ctxutils/withErr.go:31 +0x92
        created by github.com/ssbc/go-ssb/internal/ctxutils.WithError
        	/home/go-ssb/go-ssb/internal/ctxutils/withErr.go:30 +0x1df
    leakcheck.go:113: Leaked goroutine: goroutine 24 [chan receive]:
        github.com/ssbc/go-ssb/blobstore.(*WantManager).replicateLoop(0xc0000ad5e0)
        	/home/go-ssb/go-ssb/blobstore/wants.go:94 +0x57
        created by github.com/ssbc/go-ssb/blobstore.NewWantManager
        	/home/go-ssb/go-ssb/blobstore/wants.go:60 +0x30a
    leakcheck.go:113: Leaked goroutine: goroutine 25 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc000090540, {0xffc430, 0xc002218720}, {0x7fbb4451ec18?, 0xc0000a22a0?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb4451ec18?, 0xc0000a22a0?}, {0xff5c20, 0xc000090540})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 26 [select]:
        github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc002219230, 0xc002219200)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:214 +0x285
        created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:72 +0xaa
    leakcheck.go:113: Leaked goroutine: goroutine 27 [select]:
        github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc002219260, 0xc002219200)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:214 +0x285
        created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:72 +0xaa
    leakcheck.go:113: Leaked goroutine: goroutine 28 [select]:
        github.com/dgraph-io/ristretto/z.(*AllocatorPool).freeupAllocators(0xc0000a5500)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/z/allocator.go:385 +0x150
        created by github.com/dgraph-io/ristretto/z.NewAllocatorPool
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/z/allocator.go:324 +0xc5
    leakcheck.go:113: Leaked goroutine: goroutine 29 [select]:
        github.com/dgraph-io/ristretto.(*defaultPolicy).processItems(0xc00225c100)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/policy.go:102 +0x91
        created by github.com/dgraph-io/ristretto.newDefaultPolicy
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/policy.go:86 +0x156
    leakcheck.go:113: Leaked goroutine: goroutine 30 [select]:
        github.com/dgraph-io/ristretto.(*Cache).processItems(0xc0000cf180)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:452 +0x15e
        created by github.com/dgraph-io/ristretto.NewCache
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/[email protected]/cache.go:207 +0x696
    leakcheck.go:113: Leaked goroutine: goroutine 31 [select]:
        github.com/dgraph-io/badger/v3.(*DB).monitorCache(0xc00225e000, 0xc0024f54d0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:469 +0x18a
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:311 +0xc8b
    leakcheck.go:113: Leaked goroutine: goroutine 32 [select]:
        github.com/dgraph-io/badger/v3.(*DB).updateSize(0xc00225e000, 0xc0024f5620)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:1171 +0x158
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:331 +0xe8c
    leakcheck.go:113: Leaked goroutine: goroutine 33 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc002208b60, 0x0, 0xc0024f57d0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 34 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc002208b60, 0x1, 0xc0024f57d0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 35 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc002208b60, 0x2, 0xc0024f57d0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 36 [select]:
        github.com/dgraph-io/badger/v3.(*levelsController).runCompactor(0xc002208b60, 0x3, 0xc0024f57d0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:508 +0x30d
        created by github.com/dgraph-io/badger/v3.(*levelsController).startCompact
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/levels.go:354 +0x4e
    leakcheck.go:113: Leaked goroutine: goroutine 37 [chan receive]:
        github.com/dgraph-io/badger/v3.(*DB).flushMemtable(0xc00225e000, 0x0?)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:1078 +0xb2
        github.com/dgraph-io/badger/v3.Open.func5()
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:357 +0x25
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:356 +0x107c
    leakcheck.go:113: Leaked goroutine: goroutine 38 [select]:
        github.com/dgraph-io/badger/v3.(*vlogThreshold).listenForValueThresholdUpdate(0xc00225c080)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/value.go:1172 +0x11a
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:380 +0x16dc
    leakcheck.go:113: Leaked goroutine: goroutine 39 [select]:
        github.com/dgraph-io/badger/v3.(*DB).doWrites(0xc00225e000, 0xc0024f5890)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:900 +0x236
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:387 +0x179c
    leakcheck.go:113: Leaked goroutine: goroutine 40 [chan receive]:
        github.com/dgraph-io/badger/v3.(*valueLog).waitOnGC(0xc00225e1f8, 0x0?)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/value.go:1079 +0x7d
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:391 +0x185b
    leakcheck.go:113: Leaked goroutine: goroutine 41 [select]:
        github.com/dgraph-io/badger/v3.(*publisher).listenForUpdates(0xc002219320, 0xc0024f58f0)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/publisher.go:73 +0x150
        created by github.com/dgraph-io/badger/v3.Open
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/db.go:395 +0x190a
    leakcheck.go:113: Leaked goroutine: goroutine 42 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000124b90)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 43 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000124c30)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 44 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000124cd0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 45 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000124d70)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 46 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc0000ad860)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 47 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc000033980, {0xffc430, 0xc002218720}, {0x7fbb44539f38?, 0xc0000a5770?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb44539f38?, 0xc0000a5770?}, {0xff5c20, 0xc000033980})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 48 [select]:
        github.com/ssbc/margaret/indexes/badger.(*index).writeBatches(0xc0000ad900)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:178 +0xa7
        created by github.com/ssbc/margaret/indexes/badger.newIndex
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/indexes/badger/index.go:102 +0x2a5
    leakcheck.go:113: Leaked goroutine: goroutine 49 [select]:
        github.com/ssbc/margaret/multilog/roaring.(*MultiLog).writeBatches(0xc000124ff0)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:46 +0x8e
        created by github.com/ssbc/margaret/multilog/roaring.NewStore
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/multilog/roaring/multilog.go:40 +0x1b6
    leakcheck.go:113: Leaked goroutine: goroutine 50 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc0000339e0, {0xffc430, 0xc002218720}, {0xff93d0?, 0xc0022128a0?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0xff93d0?, 0xc0022128a0?}, {0xff5c20, 0xc0000339e0})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc0001385b0)
        	/home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:107 +0x168
        created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        	/home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:70 +0x1ea
    leakcheck.go:113: Leaked goroutine: goroutine 51 [select]:
        github.com/ssbc/go-ssb/network.(*Node).Serve(0xc000159440, {0xffc0b0?, 0xc00013bb00}, {0x0, 0x0, 0x0})
        	/home/go-ssb/go-ssb/network/new.go:431 +0x76d
        github.com/ssbc/go-ssb/sbot.botServer.Serve.func1()
        	/home/go-ssb/go-ssb/sbot/util_test.go:28 +0x57
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 62 [IO wait]:
        internal/poll.runtime_pollWait(0x7fbb44d66218, 0x72)
        	/usr/lib/go-1.18/src/runtime/netpoll.go:302 +0x89
        internal/poll.(*pollDesc).wait(0xc0000ce700?, 0x0?, 0x0)
        	/usr/lib/go-1.18/src/internal/poll/fd_poll_runtime.go:83 +0x32
        internal/poll.(*pollDesc).waitRead(...)
        	/usr/lib/go-1.18/src/internal/poll/fd_poll_runtime.go:88
        internal/poll.(*FD).Accept(0xc0000ce700)
        	/usr/lib/go-1.18/src/internal/poll/fd_unix.go:614 +0x22c
        net.(*netFD).accept(0xc0000ce700)
        	/usr/lib/go-1.18/src/net/fd_unix.go:172 +0x35
        net.(*TCPListener).accept(0xc00000fb48)
        	/usr/lib/go-1.18/src/net/tcpsock_posix.go:139 +0x28
        net.(*TCPListener).Accept(0xc00000fb48)
        	/usr/lib/go-1.18/src/net/tcpsock.go:288 +0x3d
        github.com/ssbc/go-netwrap.(*listener).Accept(0xc00225c840)
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/listener.go:60 +0x3e
        github.com/ssbc/go-ssb/network.(*Node).Serve.func3()
        	/home/go-ssb/go-ssb/network/new.go:414 +0xf1
        created by github.com/ssbc/go-ssb/network.(*Node).Serve
        	/home/go-ssb/go-ssb/network/new.go:405 +0x52a
    leakcheck.go:113: Leaked goroutine: goroutine 77 [select]:
        github.com/ssbc/go-ssb/internal/ctxutils.WithError.func2()
        	/home/go-ssb/go-ssb/internal/ctxutils/withErr.go:31 +0x92
        created by github.com/ssbc/go-ssb/internal/ctxutils.WithError
        	/home/go-ssb/go-ssb/internal/ctxutils/withErr.go:30 +0x1df
    leakcheck.go:113: Leaked goroutine: goroutine 78 [chan receive]:
        github.com/ssbc/go-ssb/blobstore.(*WantManager).replicateLoop(0xc00796ac80)
        	/home/go-ssb/go-ssb/blobstore/wants.go:94 +0x57
        created by github.com/ssbc/go-ssb/blobstore.NewWantManager
        	/home/go-ssb/go-ssb/blobstore/wants.go:60 +0x30a
    leakcheck.go:113: Leaked goroutine: goroutine 79 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc0000e6060, {0xffc430, 0xc00014fe60}, {0x7fbb4451ec18?, 0xc000010680?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc00014fe60}, {0x7fbb4451ec18?, 0xc000010680?}, {0xff5c20, 0xc0000e6060})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 80 [select]:
        github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc002194570, 0xc002194540)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:214 +0x285
        created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:72 +0xaa
    leakcheck.go:113: Leaked goroutine: goroutine 81 [select]:
        github.com/dgraph-io/badger/v3/y.(*WaterMark).process(0xc0021945a0, 0xc002194540)
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:214 +0x285
        created by github.com/dgraph-io/badger/v3/y.(*WaterMark).Init
        	/home/go-ssb/go/pkg/mod/github.com/dgraph-io/badger/[email protected]/y/watermark.go:72 +0xaa
    leakcheck.go:113: Leaked goroutine: goroutine 9 [select]:
        github.com/ssbc/margaret/offset2.(*offsetQuery).Push(0xc000032a80, {0xffc430, 0xc002218720}, {0x7fbb4401b118?, 0xc0001702d0?})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/offset2/qry.go:202 +0xc9
        github.com/ssbc/go-luigi.Pump({0xffc430, 0xc002218720}, {0x7fbb4401b118?, 0xc0001702d0?}, {0xff5c20, 0xc000032a80})
        	/home/go-ssb/go/pkg/mod/github.com/ssbc/[email protected]/stream.go:56 +0x82
        github.com/ssbc/go-ssb/sbot.(*Sbot).serveIndexFrom.func1()
        	/home/go-ssb/go-ssb/sbot/indexes.go:202 +0xa05
        golang.org/x/sync/errgroup.(*Group).Go.func1()
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:75 +0x64
        created by golang.org/x/sync/errgroup.(*Group).Go
        	/home/go-ssb/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:72 +0xa5
    leakcheck.go:113: Leaked goroutine: goroutine 98 [select2022/12/21 01:54:36 [margaret/indexes/badger] overwrote batch limit 0

The interesting thing is that it crashed here:

https://github.com/KyleMaas/go-ssb/blob/09cc953478e5fe29578ace24f242aebe9d71620d/sbot/null_feed_test.go#L156

...which means mainbot's log was corrupted before replication.

@KyleMaas
Copy link
Contributor Author 

2022/12/21 02:16:52 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestNullFeed
2022/12/21 02:16:52 saved identity @qlc+gGIaOVaJxt0nk7QkwkZBgY7EpvAZpLyfAypJTiI=.ed25519 to testrun/TestNullFeed/main/secrets/arny
2022/12/21 02:16:52 saved identity ssb:feed/gabbygrove-v1/SyV-h8EVgp5enWfjthTEmtvrHgq8kSQICYlc4I5naT4= to testrun/TestNullFeed/main/secrets/bert
2022/12/21 02:16:52 saved identity @aFeiAQIdvtYw9UUh0rJUETLZZ/8PCHYBJEEYtDn/Ils=.ed25519 to testrun/TestNullFeed/main/secret
    null_feed_test.go:169: starting replication
    null_feed_test.go:179: done publishing messages
    null_feed_test.go:188: connecting
level=debug t=682.037566ms bot=main TODO="found gg feed, using that. overhaul shs1 to support more payload in the handshake"
level=debug t=684.830574ms bot=main unit=gossip fr=<@aFei.ed25519> event=gossiptx n=1 starting=0
level=debug t=687.389269ms bot=bert plugin=gossip event=gossiprx fr=<@aFei.ed25519> starting=0 received=1 took=3.505706ms
level=debug t=693.491691ms bot=main plugin=gossip event=gossiprx fr=<@SyV+.gabbygrove-v1> starting=0 received=18 took=9.427454ms
level=warn t=693.723016ms bot=main plugin=gossip event="skipped updating of stored feed" err="ValidateNext(ssb:feed/gabbygrove-v1/SyV-h8EVgp5enWfjthTEmtvrHgq8kSQICYlc4I5naT4=:1): previous compare failed expected:ssb:message/gabbygrove-v1/ZEFuaQzPhN6e9y-9IFeFBwFu7EgrhiD5lA6HXUg_SN4= incoming:ssb:message/gabbygrove-v1/y9afDzC1qQ2U9nQYTg_7SzaFLB8686ARSU1euwstQHA=" fr=<@SyV+.gabbygrove-v1>
level=debug t=825.510402ms bot=bert unit=gossip fr=<@SyV+.gabbygrove-v1> event=gossiptx n=1001 starting=0
level=debug t=3.688021257s bot=bert event=update-replicate feed-want-count=1 hops=0 took=437.22µs
level=debug t=3.688192979s bot=main event=update-replicate feed-want-count=1 hops=2 took=783.266µs
    null_feed_test.go:211: sync timeout
level=warn t=25.684381128s bot=bert unit=gossip event="live qry on rxlog exited"
level=warn t=25.684557448s bot=main unit=gossip event="live qry on rxlog exited"
level=debug t=25.68668759s bot=main peer=<@SyV+.ed25519> conn="serve exited" err="muxrpc: failed to get error body for closing of req: 1 (len:66): pkt-codec: failed to read full body"
level=debug t=25.686986615s bot=bert event="network listen loop exited"
level=debug t=25.687085559s bot=main event="network listen loop exited"
level=debug t=25.687254952s bot=bert event="sbot closing" msg="connections closed"
level=debug t=25.687332693s bot=bert event="sbot closing" msg="waited for indexes to close"
level=info t=25.713594907s bot=bert event="sbot closing" msg="closers closed"
level=debug t=25.713675052s bot=main event="sbot closing" msg="connections closed"
level=debug t=25.713714488s bot=main event="sbot closing" msg="waited for indexes to close"
level=info t=25.733231453s bot=main event="sbot closing" msg="closers closed"
--- FAIL: TestNullFeed (25.73s)
FAIL
FAIL    github.com/ssbc/go-ssb/sbot     25.759s
FAIL

Here is the last debug message before it failed:

https://github.com/KyleMaas/go-ssb/blob/7304d3a3a02d8a1821cc50461143bd3809ddc8a1/sbot/null_feed_test.go#L188

Which means this one happened during replication, and several rounds of FSCK passed successfully.

@KyleMaas
Copy link
Contributor Author

I think I might have to put this one down for a while. There are way too many (very different) failure cases in this one. I think fixing some of the other tests that test smaller bits of functionality might make tracking this one down easier. This one tests a lot of stuff in one test.

@decentral1se decentral1se mentioned this issue Dec 21, 2022
Open
25 tasks
@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
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: Prioritised
Milestone
No milestone
Development

No branches or pull requests
2 participants
@decentral1se @KyleMaas