TestPrivateGroupsManualDecrypt is flaky

[decentral1se]

#237

2023/01/08 21:54:06 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestPrivateGroupsManualDecrypt
    groups_test.go:77: %qpKNP2y03haoasJ1muIPbV5u/IWYQlJKkMLevqqG43A=.cloaked 
        root: %S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256
    groups_test.go:88: {"type":"group/init","name":"hello, my group","tangles":{"group":{"root":null,"previous":null},"members":{"root":null,"previous":null}}}
    groups_test.go:93: post <%UzNO.sha256>
2023/01/08 21:57:17 saved identity @ezzoYn+g2PM0VKbEoZZfUpk+IRdXGcDs3id1T60HJW0=.ed25519 to testrun/TestPrivateGroupsManualDecrypt/tal/secret
    groups_test.go:127: added: <%ei7Y.sha256>
level=debug peer=srh unit=private-groups msg="skipping own invite"
level=debug peer=tal unit=gossip fr=<@ezzo.ed25519> event=gossiptx n=2 starting=0
level=debug peer=srh unit=gossip fr=<@TEfG.ed25519> event=gossiptx n=4 starting=0
level=debug peer=srh plugin=gossip event=gossiprx fr=<@ezzo.ed25519> starting=0 received=2 took=18.705796ms
level=debug peer=tal plugin=gossip event=gossiprx fr=<@TEfG.ed25519> starting=0 received=4 took=30.720856ms
level=debug peer=tal unit=private-groups msg="new members" author=<@TEfG.ed25519> group=<%qpKN.cloaked> members="[@ezzoYn+g2PM0VKbEoZZfUpk+IRdXGcDs3id1T60HJW0=.ed25519]"
level=debug peer=tal unit=private-groups event="joined group" id="%qpKNP2y03haoasJ1muIPbV5u/IWYQlJKkMLevqqG43A=.cloaked"
level=debug peer=tal unit=private-groups msg=reindexing group=<%qpKN.cloaked> whoToIndex="@TEfGpJMQ2Gp4yscmNWhU29AHKKS/zpa7+KCsij07V1s=.ed25519"
    groups_test.go:170: decrypted: {"type":"group/add-member","text":"welcome, tal!","version":"v1","groupKey":"aX7bJ9TGfaSGYTpVxPhcV4zd8r+LQCASOZX/rNRkgHc=","root":"%S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256","recps":["%qpKNP2y03haoasJ1muIPbV5u/IWYQlJKkMLevqqG43A=.cloaked","@ezzoYn+g2PM0VKbEoZZfUpk+IRdXGcDs3id1T60HJW0=.ed25519"],"tangles":{"group":{"root":"%S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256","previous":["%UzNOy5fgLTpc3QoePuNM5Unjvdea7oZFZ7TF/zNbPeo=.sha256"]},"members":{"root":"%S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256","previous":["%S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256"]}}}
    groups_test.go:175: 697edb27d4c67da486613a55c4f85c578cddf2bf8b4020123995ffacd4648077
    groups_test.go:184: reply: <%mRKQ.sha256>
level=debug peer=tal unit=gossip fr=<@ezzo.ed25519> event=gossiptx n=1 starting=2
level=debug peer=srh plugin=gossip event=gossiprx fr=<@ezzo.ed25519> starting=2 received=1 took=12.755052ms
    groups_test.go:202: decrypted reply: {"type":"post","text":"thanks [@sarah](@TEfGpJMQ2Gp4yscmNWhU29AHKKS/zpa7+KCsij07V1s=.ed25519)!","tangles":{"group":{"root":"%S6FKwPFNBIQGhMvZCl8wuPOsyGAJFEqY1nZkqRxDHZE=.sha256","previous":["%ei7YlSTX3fMPn1pnDkD2OYMSnSHqn6BV1OJ1sB6Aa7E=.sha256"]}},"recps":["%qpKNP2y03haoasJ1muIPbV5u/IWYQlJKkMLevqqG43A=.cloaked"]}
    groups_test.go:214: "index-address:\"string:test\"": [0 4]
    groups_test.go:214: "index-address:\"string:post\"": [2 6]
    groups_test.go:214: "index-address:\"string:test\"": [0 2]
    groups_test.go:214: "index-address:\"string:post\"": [4 6]
    groups_test.go:214: "index-address:\"box2:\\x00\\x00LGƤ\\x93\\x10\\xd8jx\\xca\\xc7&5hT\\xdb\\xd0\\a(\\xa4\\xbfΖ\\xbb\\xf8\\xa0\\xac\\x8a=;W[\"": [2 3 6]
    groups_test.go:214: "index-address:\"box2:\\x00\\x00{<\\xe8b\\u007f\\xa0\\xd8\\xf34T\\xa6ġ\\x96_R\\x99>!\\x17W\\x19\\xc0\\xec\\xde'uO\\xad\\a%m\"": [3 4 5 6]
    groups_test.go:233: all boxed: 
        [000] Key:      0x0. Offset:      24. Size:   64. Type: 0. Card:      4. Uint16/Uid: 16.00
        Number of containers: 1. Cardinality: 4
        Size in Uint16s. Used: 68. Total: 88. Space Amplification: 29.41%. Moved: 0.00x
        Used Uint16/Uid: 17.00. Total Uint16/Uid: 22.00
level=debug peer=tal event="network listen loop exited"
level=warn peer=tal unit=gossip event="live qry on rxlog exited"
level=warn peer=srh unit=gossip event="live qry on rxlog exited"
peer=tal event=warning msg="still open connections" count=1
level=debug peer=tal event="sbot closing" msg="connections closed"
level=debug peer=tal event="sbot c2023/01/08 21:57:25 [margaret/indexes/badger] overwrote batch limit 0
=== RUN   TestPrivateGroupsManualDecrypt
    groups_test.go:77: %2dk+iABUHTpY385kVBUVa7FBZutQ6/lOREDoM8PGw3s=.cloaked 
        root: %ttdMi7IncawDgSqOhmx0jl89CkHdyrxCYLkb8+JTp9U=.sha256
    groups_test.go:88: {"type":"group/init","name":"hello, my group","tangles":{"group":{"root":null,"previous":null},"members":{"root":null,"previous":null}}}
    groups_test.go:93: post <%sdS5.sha256>
2023/01/08 21:57:25 saved identity @q2KvIdjac0ffQI2DdF4zFppcdZkjlT43P/dhzlzm3WQ=.ed25519 to testrun/TestPrivateGroupsManualDecrypt/tal/secret
    groups_test.go:127: added: <%ssTP.sha256>
level=debug peer=srh unit=private-groups msg="skipping own invite"
level=debug peer=tal unit=gossip fr=<@q2Kv.ed25519> event=gossiptx n=2 starting=0
level=debug peer=srh unit=gossip fr=<@TEfG.ed25519> event=gossiptx n=4 starting=0
level=debug peer=srh plugin=gossip event=gossiprx fr=<@q2Kv.ed25519> starting=0 received=2 took=7.501475ms
level=debug peer=tal plugin=gossip event=gossiprx fr=<@TEfG.ed25519> starting=0 received=4 took=11.571078ms
level=debug peer=tal unit=private-groups msg="new members" author=<@TEfG.ed25519> group=<%2dk+.cloaked> members="[@q2KvIdjac0ffQI2DdF4zFppcdZkjlT43P/dhzlzm3WQ=.ed25519]"
level=debug peer=tal unit=private-groups event="joined group" id="%2dk+iABUHTpY385kVBUVa7FBZutQ6/lOREDoM8PGw3s=.cloaked"
level=debug peer=tal unit=private-groups msg=reindexing group=<%2dk+.cloaked> whoToIndex="@TEfGpJMQ2Gp4yscmNWhU29AHKKS/zpa7+KCsij07V1s=.ed25519"
    groups_test.go:159: 
        	Error Trace:	/home/d/work/ssb/go-ssb/sbot/groups_test.go:159
        	Error:      	Not equal: 
        	            	expected: int(1)
        	            	actual  : int64(0)
        	Test:       	TestPrivateGroupsManualDecrypt
--- FAIL: TestPrivateGroupsManualDecrypt (1.15s)
FAIL
FAIL	github.com/ssbc/go-ssb/sbot	1.195s
FAIL

[KyleMaas]

So...this one's going to be a little tricky to debug. I've run it a little over 100 times now with zero failures. There are plenty of possibilities for race conditions, several of which we've already solved. So this might or might not already be fixed. One way or another, it's rare enough that it's going to be hard to know for sure if and when it has actually been fixed.

[KyleMaas]

I think a lot of this may have been fixed by the Publish stuff becoming synchronous. It means it has to slow down the test a little bit and do things in order, which makes it more likely to have been fully processed by the time it tries to replicate the data into the second bot. I'm sure the problem's still there, but it's likely even more rare (and thus flaky) now than before.