TestMigrate test flaky #257

KyleMaas · 2022-12-18T00:57:23Z

Working through the list in #237

Several fail runs:

2022/12/18 00:49:50 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestMigrate
2022/12/18 00:49:50 saved identity @fjJ93uU89TWPhUWXcMMArwRWtdnZxaEa2RrCD5Hg1Xk=.ed25519 to testrun/TestMigrate/secret
level=debug ts=2022-12-18T00:49:50.989885925Z caller=new.go:909 event="sbot closing" msg="connections closed"
level=warn ts=2022-12-18T00:49:50.990041421Z caller=feed_manager.go:111 unit=gossip event="live qry on rxlog exited"
level=debug ts=2022-12-18T00:49:50.990543652Z caller=new.go:916 event="sbot closing" msg="waited for indexes to close"
level=info ts=2022-12-18T00:49:51.00496445Z caller=new.go:923 event="sbot closing" msg="closers closed"
gossb-migrate-mf: load classic keypair
gossb-migrate-mf: move backup
gossb-migrate-mf: get metafeed id
2022/12/18 00:49:51 saved identity ssb:feed/bendybutt-v1/9RlGVfFfwJxCx87YZyhVsCfGIo1vrISToZG5sYCTTT4= to testrun/TestMigrate/secret
gossb-migrate-mf: root mf id is ssb:feed/bendybutt-v1/9RlGVfFfwJxCx87YZyhVsCfGIo1vrISToZG5sYCTTT4=
panic: error while serving live feed: error read offset of seq(8): seek failed:seek testrun/TestMigrate/log/ofst: file already closed

goroutine 169 [running]:
github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc00022c230)
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:109 +0x32e
created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:69 +0x1ea
FAIL    github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.105s
FAIL

2022/12/18 00:51:09 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestMigrate
2022/12/18 00:51:09 saved identity @eShpek72A0fthSgK3b/rkC9Nhj0P/lU6Sdv8R9ET+1Q=.ed25519 to testrun/TestMigrate/secret
level=warn ts=2022-12-18T00:51:09.991176507Z caller=feed_manager.go:111 unit=gossip event="live qry on rxlog exited"
level=debug ts=2022-12-18T00:51:09.991502244Z caller=new.go:909 event="sbot closing" msg="connections closed"
level=debug ts=2022-12-18T00:51:09.991575181Z caller=new.go:916 event="sbot closing" msg="waited for indexes to close"
level=info ts=2022-12-18T00:51:10.00499768Z caller=new.go:923 event="sbot closing" msg="closers closed"
gossb-migrate-mf: load classic keypair
gossb-migrate-mf: move backup
gossb-migrate-mf: get metafeed id
2022/12/18 00:51:10 saved identity ssb:feed/bendybutt-v1/DTB5SUgGB62KV9kTGbCjbwYbr5OnJ8vpymPx-TaK2g4= to testrun/TestMigrate/secret
gossb-migrate-mf: root mf id is ssb:feed/bendybutt-v1/DTB5SUgGB62KV9kTGbCjbwYbr5OnJ8vpymPx-TaK2g4=
panic: error while serving live feed: error read offset of seq(8): seek failed:seek testrun/TestMigrate/log/ofst: file already closed

goroutine 181 [running]:
github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc00018e2a0)
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:109 +0x32e
created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:69 +0x1ea
FAIL    github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.108s
FAIL

ok      github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.222s
2022/12/18 00:51:48 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestMigrate
2022/12/18 00:51:48 saved identity @+hMB9i/tRmRrg4MMs/ZelR4+TP/KbZ6b5khL6L5MQc0=.ed25519 to testrun/TestMigrate/secret
level=debug ts=2022-12-18T00:51:48.720470718Z caller=new.go:909 event="sbot closing" msg="connections closed"
level=warn ts=2022-12-18T00:51:48.720793905Z caller=feed_manager.go:111 unit=gossip event="live qry on rxlog exited"
level=debug ts=2022-12-18T00:51:48.720924652Z caller=new.go:916 event="sbot closing" msg="waited for indexes to close"
level=info ts=2022-12-18T00:51:48.736577951Z caller=new.go:923 event="sbot closing" msg="closers closed"
gossb-migrate-mf: load classic keypair
gossb-migrate-mf: move backup
gossb-migrate-mf: get metafeed id
2022/12/18 00:51:48 saved identity ssb:feed/bendybutt-v1/8l8VtLmu6aeddOkRbgXMLNOcHsXmzlYuE84dVwn4u4M= to testrun/TestMigrate/secret
gossb-migrate-mf: root mf id is ssb:feed/bendybutt-v1/8l8VtLmu6aeddOkRbgXMLNOcHsXmzlYuE84dVwn4u4M=
panic: error while serving live feed: error read offset of seq(8): seek failed:seek testrun/TestMigrate/log/ofst: file already closed

goroutine 168 [running]:
github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc0000a6690)
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:109 +0x32e
created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:69 +0x1ea
FAIL    github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.111s
FAIL

2022/12/18 00:51:57 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestMigrate
2022/12/18 00:51:57 saved identity @GjeyP7V5qMaR/77pK6QUMK+0m4n4/ZilfbrYC7k78ZY=.ed25519 to testrun/TestMigrate/secret
level=debug ts=2022-12-18T00:51:57.215433383Z caller=new.go:909 event="sbot closing" msg="connections closed"
level=warn ts=2022-12-18T00:51:57.215759434Z caller=feed_manager.go:111 unit=gossip event="live qry on rxlog exited"
level=debug ts=2022-12-18T00:51:57.216023211Z caller=new.go:916 event="sbot closing" msg="waited for indexes to close"
level=info ts=2022-12-18T00:51:57.231063718Z caller=new.go:923 event="sbot closing" msg="closers closed"
gossb-migrate-mf: load classic keypair
gossb-migrate-mf: move backup
gossb-migrate-mf: get metafeed id
2022/12/18 00:51:57 saved identity ssb:feed/bendybutt-v1/8BKNEj-Sroh2dZRz6cIJKm13oJmGGtpjhkvnjWYBEx8= to testrun/TestMigrate/secret
gossb-migrate-mf: root mf id is ssb:feed/bendybutt-v1/8BKNEj-Sroh2dZRz6cIJKm13oJmGGtpjhkvnjWYBEx8=
panic: error while serving live feed: error read offset of seq(8): seek failed:seek testrun/TestMigrate/log/ofst: file already closed

goroutine 169 [running]:
github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc00013a700)
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:109 +0x32e
created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:69 +0x1ea
FAIL    github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.104s
FAIL

2022/12/18 00:52:01 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestMigrate
2022/12/18 00:52:01 saved identity @YnuAsVYURBKnLdzh2l1r3JqzbszXv9IIkmbGF+EDbZM=.ed25519 to testrun/TestMigrate/secret
level=debug ts=2022-12-18T00:52:01.569831636Z caller=new.go:909 event="sbot closing" msg="connections closed"
level=warn ts=2022-12-18T00:52:01.570011342Z caller=feed_manager.go:111 unit=gossip event="live qry on rxlog exited"
level=debug ts=2022-12-18T00:52:01.57037072Z caller=new.go:916 event="sbot closing" msg="waited for indexes to close"
level=info ts=2022-12-18T00:52:01.580336021Z caller=new.go:923 event="sbot closing" msg="closers closed"
gossb-migrate-mf: load classic keypair
gossb-migrate-mf: move backup
gossb-migrate-mf: get metafeed id
2022/12/18 00:52:01 saved identity ssb:feed/bendybutt-v1/s6gwna9pPqoLzq-k1wJSXOffEcKme-8ZVELTc5BjPkY= to testrun/TestMigrate/secret
gossb-migrate-mf: root mf id is ssb:feed/bendybutt-v1/s6gwna9pPqoLzq-k1wJSXOffEcKme-8ZVELTc5BjPkY=
panic: error while serving live feed: error read offset of seq(8): seek failed:seek testrun/TestMigrate/log/ofst: file already closed

goroutine 122 [running]:
github.com/ssbc/go-ssb/plugins/gossip.(*FeedManager).serveLiveFeeds(0xc00018e230)
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:109 +0x32e
created by github.com/ssbc/go-ssb/plugins/gossip.NewFeedManager
        /home/go-ssb/go-ssb/plugins/gossip/feed_manager.go:69 +0x1ea
FAIL    github.com/ssbc/go-ssb/cmd/gossb-migrate-mf/migrate     0.071s
FAIL

Observation: it's remarkably consistent.

The text was updated successfully, but these errors were encountered:

KyleMaas · 2022-12-18T01:22:20Z

Problem appears to be happening in this line:

go-ssb/cmd/gossb-migrate-mf/migrate/migrate_test.go

Line 73 in 83f9097

mfId, err := getMetafeedID(tRepoPath)

KyleMaas · 2022-12-18T19:21:56Z

More specifically, it happens here:

go-ssb/sbot/new.go

Line 918 in 83f9097

if err := s.closers.Close(); err != nil {

KyleMaas · 2022-12-18T19:32:05Z

Looks like someone ran into something similar before:

https://github.com/ssbc/go-muxrpc/blob/b09bdf60812fb12a3f7060f85f078a84712acbfa/debug/debug.go#L134

decentral1se moved this to In Progress in 🚧 go-ssb maintenance 🚧 Dec 18, 2022

decentral1se added this to 🚧 go-ssb maintenance 🚧 Dec 18, 2022

decentral1se mentioned this issue Dec 18, 2022

Fix flaky tests #237

Open

25 tasks

decentral1se added the testing label Dec 18, 2022

KyleMaas mentioned this issue Dec 18, 2022

Fix TestMigrate #264

Merged

decentral1se closed this as completed in #264 Dec 18, 2022

Repository owner moved this from In Progress to Done in 🚧 go-ssb maintenance 🚧 Dec 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

TestMigrate test flaky #257

TestMigrate test flaky #257

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022

TestMigrate test flaky #257

TestMigrate test flaky #257

Comments

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022

KyleMaas commented Dec 18, 2022