search

dedis / prifi

PriFi, a low-latency, local-area anonymous communication network.
https://prifi.net
GNU Affero General Public License v3.0
48 stars 11 forks source link

Concurrency bug when timeout #185

Closed lbarman closed 6 years ago

lbarman commented 6 years ago 
1 : (relay.(*PriFiLibRelayInstance).checkIfRoundHasEndedAfterTimeOut_Phase1:  33) - WARNING: Timeout for round 1141 , force closing. Already 1 consecutive missed rounds (killing when => 3 )
1 : (relay.(*PriFiLibRelayInstance).checkIfRoundHasEndedAfterTimeOut_Phase1:  38) - missing clients [] and trustees []
1 : (relay.(*PriFiLibRelayInstance).checkIfRoundHasEndedAfterTimeOut_Phase1:  49) - Gonna Force close...
1 : (                                  relay.(*BufferableRoundManager).Dump:  86) - ------------------------
1 : (                                  relay.(*BufferableRoundManager).Dump:  87) - BufferableRoundManager with  3 clients 1 trustees, window = 1
1 : (                                  relay.(*BufferableRoundManager).Dump:  89) - Current round: 1141 open= true Has all ciphers ?  true
1 : (                                  relay.(*BufferableRoundManager).Dump:  91) - Open rounds: 1141 2018-04-01 14:12:28.681132687 +0200 CEST m=+6.788399380
1 : (                                  relay.(*BufferableRoundManager).Dump:  93) - ACK MAP Clients
1 : (                                                relay.sortedIntMapDump:  77) -  0: true
1 : (                                                relay.sortedIntMapDump:  77) -  1: true
1 : (                                                relay.sortedIntMapDump:  77) -  2: true
1 : (                                  relay.(*BufferableRoundManager).Dump:  95) - ACK MAP Trustees
1 : (                                                relay.sortedIntMapDump:  77) -  0: true
1 : (                                  relay.(*BufferableRoundManager).Dump: 101) - ------------------------
1 : (                                  relay.(*BufferableRoundManager).Dump:  86) - ------------------------
1 : (                                  relay.(*BufferableRoundManager).Dump:  87) - BufferableRoundManager with  3 clients 1 trustees, window = 1
1 : (                                  relay.(*BufferableRoundManager).Dump:  89) - Current round: -1 open= false Has all ciphers ?  false
1 : (                                  relay.(*BufferableRoundManager).Dump:  93) - ACK MAP Clients
1 : (                                                relay.sortedIntMapDump:  77) -  0: false
1 : (                                                relay.sortedIntMapDump:  77) -  1: false
1 : (                                                relay.sortedIntMapDump:  77) -  2: false
1 : (                                  relay.(*BufferableRoundManager).Dump:  95) - ACK MAP Trustees
1 : (                                                relay.sortedIntMapDump:  77) -  0: false
1 : (                                  relay.(*BufferableRoundManager).Dump: 101) - ------------------------
3 : (               relay.(*PriFiLibRelayInstance).downstreamPhase_sendMany: 304) - Relay : Gonna send, non-acked packets is 0 (window is 1 )
2 : (  relay.(*PriFiLibRelayInstance).downstreamPhase1_openRoundAndSendData: 563) - Relay is gonna broadcast messages for round 1142 (OCRequest=false), owner= -1 , len 5000
3 : (                               prifi-lib.newMessageSenderWrapper.func2: 101) - Sent a *net.REL_CLI_DOWNSTREAM_DATA.(client 0, round 1142)
3 : (                               prifi-lib.newMessageSenderWrapper.func2: 101) - Sent a *net.REL_CLI_DOWNSTREAM_DATA.(client 1, round 1142)
3 : (                               prifi-lib.newMessageSenderWrapper.func2: 101) - Sent a *net.REL_CLI_DOWNSTREAM_DATA.(client 2, round 1142)
3 : (  relay.(*PriFiLibRelayInstance).downstreamPhase1_openRoundAndSendData: 599) - Relay is done broadcasting messages for round 1142.
E : (                      relay.(*BufferableRoundManager).TimeSpentInRound: 388) - Requested duration for round 1141 , but round has been closed already (or was not found).
2 : (           relay.(*PriFiLibRelayInstance).upstreamPhase3_finalizeRound: 473) - Relay finished round 1141 (after 0s ).
E : (                      relay.(*BufferableRoundManager).TimeSpentInRound: 388) - Requested duration for round 1141 , but round has been closed already (or was not found).
3 : (               relay.(*PriFiLibRelayInstance).downstreamPhase_sendMany: 304) - Relay : Gonna send, non-acked packets is 0 (window is 1 )
2 : (  relay.(*PriFiLibRelayInstance).downstreamPhase1_openRoundAndSendData: 561) - Relay is gonna broadcast messages for round 1143 (OCRequest=true), owner= -1 , len 5000
goroutine 218 [running]:
runtime/debug.Stack(0xc400000008, 0xc42052c380, 0xc420256d40)
    /usr/lib/golang/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
    /usr/lib/golang/src/runtime/debug/stack.go:16 +0x22
github.com/lbarman/prifi/prifi-lib/relay.(*BufferableRoundManager).OpenNextRound(0xc4200944d0, 0x47600000000)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/bufferableRoundManager.go:235 +0x35c
github.com/lbarman/prifi/prifi-lib/relay.(*PriFiLibRelayInstance).downstreamPhase1_openRoundAndSendData(0xc42014fc00, 0x5, 0x5)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/relay.go:578 +0x39b
github.com/lbarman/prifi/prifi-lib/relay.(*PriFiLibRelayInstance).downstreamPhase_sendMany(0xc42014fc00)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/relay.go:305 +0x14d
github.com/lbarman/prifi/prifi-lib/relay.(*PriFiLibRelayInstance).upstreamPhase1_processCiphers(0xc42014fc00, 0x400)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/relay.go:296 +0x31b
github.com/lbarman/prifi/prifi-lib/relay.(*PriFiLibRelayInstance).Received_CLI_REL_OPENCLOSED_DATA(0xc42014fc00, 0x2, 0x475, 0xc42025c119, 0x1390, 0x1390, 0x0, 0x0)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/relay.go:244 +0xbb
github.com/lbarman/prifi/prifi-lib/relay.(*PriFiLibRelayInstance).ReceivedMessage(0xc42014fc00, 0x89ad20, 0xc4203663c0, 0x40fff4, 0x89ad20)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/relay/init.go:204 +0xccc
github.com/lbarman/prifi/prifi-lib.(*PriFiLibInstance).ReceivedMessage(0xc420310c60, 0x89ad20, 0xc4203663c0, 0xc4203663c0, 0xa0000000020)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/prifi-lib/prifi.go:90 +0x4c
github.com/lbarman/prifi/sda/protocols.(*PriFiSDAProtocol).Received_CLI_REL_CLI_REL_OPENCLOSED_DATA(0xc4201d42c0, 0xc420196b90, 0x2, 0x475, 0xc42025c119, 0x1390, 0x1390, 0xc4202576f0, 0x41357c)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/sda/protocols/message_binders.go:37 +0x80
github.com/lbarman/prifi/sda/protocols.(*PriFiSDAProtocol).Received_CLI_REL_CLI_REL_OPENCLOSED_DATA-fm(0xc420196b90, 0x2, 0x475, 0xc42025c119, 0x1390, 0x1390, 0x0, 0x0)
    /home/jwhite/d/go/src/github.com/lbarman/prifi/sda/protocols/protocol.go:221 +0x47
reflect.Value.call(0x852b20, 0xc420320770, 0x13, 0x8f30ac, 0x4, 0xc420257c20, 0x1, 0x1, 0xc420366390, 0xc420366398, ...)
    /usr/lib/golang/src/reflect/value.go:434 +0x905
reflect.Value.Call(0x852b20, 0xc420320770, 0x13, 0xc420257c20, 0x1, 0x1, 0x199, 0xc420257b48, 0x412367)
    /usr/lib/golang/src/reflect/value.go:302 +0xa4
gopkg.in/dedis/onet%2ev1.(*TreeNodeInstance).dispatchHandler(0xc4203864e0, 0xc42000e130, 0x1, 0x1, 0x3, 0x1)
    /home/jwhite/d/go/src/gopkg.in/dedis/onet.v1/treenode.go:336 +0x3be
gopkg.in/dedis/onet%2ev1.(*TreeNodeInstance).dispatchMsgToProtocol(0xc4203864e0, 0xc420197680, 0x3, 0xc42040f288)
    /home/jwhite/d/go/src/gopkg.in/dedis/onet.v1/treenode.go:456 +0x50d
gopkg.in/dedis/onet%2ev1.(*TreeNodeInstance).dispatchMsgReader(0xc4203864e0)
    /home/jwhite/d/go/src/gopkg.in/dedis/onet.v1/treenode.go:424 +0x205
created by gopkg.in/dedis/onet%2ev1.newTreeNodeInstance
    /home/jwhite/d/go/src/gopkg.in/dedis/onet.v1/treenode.go:86 +0x2fe
F : (                         relay.(*BufferableRoundManager).OpenNextRound: 236) - Tried to OpenNextRound(), but we have already 1 rounds opened (max 1 ).