search

signetlabdei / quic-ns-3

QUIC implementation for ns-3
GNU General Public License v2.0
44 stars 17 forks source link

Nondeterministic simulation behavior. #18

Open tnull opened 3 years ago

tnull commented 3 years ago

I'm still trying to figure out why I'm seeing a lot of duplicate packets in my simulations that are then dropped by the RX buffer (see https://github.com/signetlabdei/quic-ns-3/issues/16). While debugging, I found that individual simulation runs start diverging from a certain point, i.e., they become nondeterministic, even when a global seed value is set via ns3::RngSeedManager::SetSeed (seed). This should not be the case.

More interestingly however, is the protocol behavior at the point where the simulation runs diverge, here are the outputs of two such runs: 

+7.093431120s 6  [node 6] QuicL4Protocol:ForwardUp(): [INFO ] Receiving packet on UDP socket
+7.093431120s 6 QuicL5Protocol:CreateStream(): [INFO ] Create stream 0
+7.093431120s 6 QuicL5Protocol:CreateStream(): [INFO ] Create the stream with ID 0
+7.093431120s 6 QuicStreamBase:SetMaxStreamData(): [DEBUG] Update max stream data from 0 to 4294967295
+7.093431120s 6 QuicSocketBase:Connect(): [INFO ] CONNECTION not authenticated: cannot perform 0-RTT Handshake
+7.093431120s 6 QuicSocketBase:SetState(): [INFO ] Server LISTENING -> CONNECTING_SVR
+7.093431120s 6 QuicSocketBase:ReceivedData(): [INFO ] Received packet of size 1204
+7.093431120s 6 QuicSocketBase:ReceivedData(): [INFO ] Server receives INITIAL
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] DisgregateRecv for a packet with size 1204
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] subheader |STREAM010|
|Stream Id 0|
|Length 1200|
 dataSizeByte 1204 remaining 1200 frame size 1200
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] fragment size 1200
+7.093431120s 6 QuicL5Protocol:DispatchRecv(): [INFO ] Receiving frame on stream 0 trigger stream
+7.093431120s 6 QuicStreamBase:SetStreamStateRecv(): [INFO ] Client Stream IDLE -> RECV
+7.093431120s 6 QuicStreamBase:Recv(): [INFO ] Received a frame with the correct order of size 1200
+7.093431120s 6 QuicSocketBase:AvailableWindow(): [DEBUG] m_max_data 4294967295 m_tcb->m_cWnd.Get () 0
+7.093431120s 6 QuicSocketBase:BytesInFlight(): [INFO ] Returning calculated bytesInFlight: 0
+7.093431120s 6 QuicSocketBase:AvailableWindow(): [INFO ] InFlight=0, Win=0 availWin=0
+7.093431120s 6 QuicSocketBase:AppendingTx(): [DEBUG] Added packet to the buffer - txBufSize = 5 AvailableWindow = 0 state CONNECTING_SVR
+7.093431120s 6 QuicStreamBase:Recv(): [INFO ] Received handshake Message in Stream 0
+7.093431120s 6 QuicSocketBase:SendInitialHandshake(): [INFO ] Create HANDSHAKE
+7.093431120s 6 QuicL5Protocol:DispatchSend(): [INFO ] Send packet on (specified) stream 0
+7.093431120s 6 QuicStreamBase:SetStreamStateSend(): [INFO ] Client Stream IDLE -> OPEN
+7.093431120s 6 QuicStreamTxBuffer:Add(): [INFO ] Try to append 0 bytes , availSize=10485760
+7.093431120s 6 QuicStreamTxBuffer:Add(): [WARN ] Discarded. Try to insert empty packet.

vs.

+7.093431120s 6  [node 6] QuicL4Protocol:ForwardUp(): [INFO ] Receiving packet on UDP socket
+7.093431120s 6 QuicL5Protocol:CreateStream(): [INFO ] Create stream 0
+7.093431120s 6 QuicL5Protocol:CreateStream(): [INFO ] Create the stream with ID 0
+7.093431120s 6 QuicStreamBase:SetMaxStreamData(): [DEBUG] Update max stream data from 0 to 4294967295
+7.093431120s 6 QuicSocketBase:Connect(): [INFO ] CONNECTION not authenticated: cannot perform 0-RTT Handshake
+7.093431120s 6 QuicSocketBase:SetState(): [INFO ] Server LISTENING -> CONNECTING_SVR
+7.093431120s 6 QuicSocketBase:ReceivedData(): [INFO ] Received packet of size 1204
+7.093431120s 6 QuicSocketBase:ReceivedData(): [INFO ] Server receives INITIAL
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] DisgregateRecv for a packet with size 1204
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] subheader |STREAM010|
|Stream Id 0|
|Length 1200|
 dataSizeByte 1204 remaining 1200 frame size 1200
+7.093431120s 6 QuicL5Protocol:DisgregateRecv(): [INFO ] fragment size 1200
+7.093431120s 6 QuicL5Protocol:DispatchRecv(): [INFO ] Receiving frame on stream 0 trigger stream
+7.093431120s 6 QuicStreamBase:SetStreamStateRecv(): [INFO ] Client Stream IDLE -> RECV
+7.093431120s 6 QuicStreamBase:Recv(): [INFO ] Received a frame with the correct order of size 1200
+7.093431120s 6 QuicSocketBase:AvailableWindow(): [DEBUG] m_max_data 4294967295 m_tcb->m_cWnd.Get () 0
+7.093431120s 6 QuicSocketBase:BytesInFlight(): [INFO ] Returning calculated bytesInFlight: 0
+7.093431120s 6 QuicSocketBase:AvailableWindow(): [INFO ] InFlight=0, Win=0 availWin=0
+7.093431120s 6 QuicSocketBase:AppendingTx(): [DEBUG] Added packet to the buffer - txBufSize = 5 AvailableWindow = 0 state CONNECTING_SVR
+7.093431120s 6 QuicStreamBase:Recv(): [INFO ] Received handshake Message in Stream 0
+7.093431120s 6 QuicSocketBase:SendInitialHandshake(): [INFO ] Create HANDSHAKE
+7.093431120s 6 QuicL5Protocol:DispatchSend(): [INFO ] Send packet on (specified) stream 0
+7.093431120s 6 QuicStreamBase:SetStreamStateSend(): [INFO ] Client Stream IDLE -> OPEN
+7.093431120s 6 QuicStreamTxBuffer:Add(): [INFO ] Try to append 104923235 bytes , availSize=10485760
+7.093431120s 6 QuicStreamTxBuffer:Add(): [WARN ] Rejected. Not enough room to buffer packet.

Notably, there is a tremendous difference in the sizes of the initial packets after the handshake (0 vs. 104923235, I'm also seeing other values, such as 1763730810). I just confirmed this to happen on my macOS laptop as well as a Ubuntu Linux machine.

Does anyone have an idea where these differences could come from? As values seem to be random, my intuition is that there may be an uninitialized variable lingering somewhere?