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

zero_rtt test case against devqa.akaquic.com:443 is occasionally crashing on SIGSEGV #32

Open
vranem1 opened this issue Sep 13, 2022 · 5 comments
Open

zero_rtt test case against devqa.akaquic.com:443 is occasionally crashing on SIGSEGV #32

vranem1 opened this issue Sep 13, 2022 · 5 comments

Comments

@vranem1
Copy link

vranem1 commented Sep 13, 2022

`[44d1209ef7cdd38e/QLogAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/SocketAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/ParsingAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/BufferAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/TLSAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/AckAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/SendingAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/RecoveryAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/RTTAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/FrameQueueAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/FlowControlAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/StreamAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/ClosingAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/HandshakeAgent] base_agent.go:49: Agent started
[44d1209ef7cdd38e/HandshakeAgent] handshake_agent.go:59: Sending first Initial packet
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=Initial, number=0}
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 1252 bytes from UDP socket
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 1252 bytes from UDP socket
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 1252 bytes from UDP socket
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of Initial packet of length 1252 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=Initial, number=1}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=Initial, number=1, length=1236}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:73: Crypto state for Handshake packet of length 1252 bytes is not ready, putting it back in waiting buffer
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:73: Crypto state for Handshake packet of length 1252 bytes is not ready, putting it back in waiting buffer
[44d1209ef7cdd38e/RTTAgent] rtt_agent.go:125: LatestRTT = 27723, MinRTT = 27723, SmoothedRTT = 27723, RTTVar = 13861
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received Initial packet in PN space Initial and 123 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:65: Processing ACK frame in packet {type=Initial, number=1}
[44d1209ef7cdd38e/HandshakeAgent] handshake_agent.go:92: Received first Initial packet from server, switching DCID to 44d1209ef7cdd38e
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:93: Installing handshake read crypto with secret b514eca2777a349e3a8b498c234e7747766634601596d46519d6c77e5fefce97b24eff30031f039cd36950152818d0be
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:97: Installing handshake write crypto with secret cd3e546aab77230894f0695bd8127b57f0e6671613aebe448b625343475f287bcd4195627ee02f0b2a07d487d4fa2895
[44d1209ef7cdd38e/BufferAgent] buffer_agent.go:44: Encryption level Handshake is available, putting back 2 unprocessed payloads into the buffer
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of Handshake packet of length 1252 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=Handshake, number=2}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=Handshake, number=2, length=1236}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of Handshake packet of length 1252 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=Handshake, number=3}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=Handshake, number=3, length=1236}
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received Handshake packet in PN space Handshake and 2411 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received Handshake packet in PN space Handshake and 0 bytes from the corresponding crypto stream
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=Initial, number=1}
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=Handshake, number=0}
[44d1209ef7cdd38e/SendingAgent] send_agent.go:101: Chose Handshake as new encryption level for Best
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=Handshake, number=1}
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 1252 bytes from UDP socket
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 951 bytes from UDP socket
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of Handshake packet of length 1252 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=Handshake, number=4}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=Handshake, number=4, length=1236}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of Handshake packet of length 951 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=Handshake, number=5}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=Handshake, number=5, length=935}
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received Handshake packet in PN space Handshake and 2109 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:109: Handshake has completed, installing protected crypto {read=9c783daf263c340316632542e3141a0eaac7d12786d25d703d0dfb4f43c327dcd8f09beb5cbb8e7e39206e77585dbba1, write=abd2d08500e2de0bf0e3720fd1aa273447794c523f8e89ea2c3874b72e15fe3a473bdc8e23a5ce43a0abb7fb4d70fd6e}
[44d1209ef7cdd38e/FrameQueueAgent] frame_queue_agent.go:122: Received a 0x06 frame for encryption level Handshake
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received Handshake packet in PN space Handshake and 0 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:110: Handshake has completed, emptying the two retransmission buffers
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:110: Handshake has completed, emptying the two retransmission buffers
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=Handshake, number=2}
[44d1209ef7cdd38e/SendingAgent] send_agent.go:81: Preparing a packet for encryption level 1RTT resulted in an empty packet, discarding
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 280 bytes from UDP socket
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 296 bytes from UDP socket
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 72 bytes from UDP socket
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of 1-RTT Protected packet of length 280 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=1-RTT Protected, number=6}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=1-RTT Protected, number=6, length=264}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of 1-RTT Protected packet of length 296 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=1-RTT Protected, number=7}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=1-RTT Protected, number=7, length=280}
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:67: Received 33 bytes from UDP socket
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of 1-RTT Protected packet of length 72 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=1-RTT Protected, number=8}
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received 1-RTT Protected packet in PN space Application data and 514 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=1-RTT Protected, number=8, length=56}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:51: Decrypting packet number of 1-RTT Protected packet of length 33 bytes
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:80: Successfully decrypted header {type=1-RTT Protected, number=9}
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:137: Successfully parsed packet {type=1-RTT Protected, number=9, length=17}
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received 1-RTT Protected packet in PN space Application data and 0 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received 1-RTT Protected packet in PN space Application data and 0 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:74: Received 1-RTT Protected packet in PN space Application data and 0 bytes from the corresponding crypto stream
[44d1209ef7cdd38e/FlowControlAgent] flow_control_agent.go:74: Initialised stream 3 read limit to 16384 bytes
[44d1209ef7cdd38e/SendingAgent] send_agent.go:151: Dropping encryption level Initial
[44d1209ef7cdd38e/SendingAgent] send_agent.go:151: Dropping encryption level Handshake
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:115: Dropping Initial encryption level, emptying the retransmission buffer
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:119: Dropping Handshake encryption level, emptying the retransmission buffer
[44d1209ef7cdd38e/HandshakeAgent] handshake_agent.go:177: New status HandshakeStatus{Completed=true, Error=%!s()}
[44d1209ef7cdd38e/FrameQueueAgent] frame_queue_agent.go:122: Received a 0x1d frame for encryption level Best
[44d1209ef7cdd38e/SendingAgent] send_agent.go:101: Chose 1RTT as new encryption level for Best
[CID 44d1209ef7cdd38e] connection.go:150: Sending packet {type=1-RTT Protected, number=0}
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:99: Connection is closing, emptying retransmit buffers
[44d1209ef7cdd38e/ClosingAgent] closing_agent.go:40: Agent terminated
[44d1209ef7cdd38e/RecoveryAgent] recovery_agent.go:132: Agent terminated
[44d1209ef7cdd38e/FlowControlAgent] flow_control_agent.go:276: Agent terminated
[44d1209ef7cdd38e/QLogAgent] qlog_agent.go:44: Agent terminated
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:37: Closing UDP socket because of error read udp 172.24.73.222:39694->3.127.187.4:443: use of closed network connection
[44d1209ef7cdd38e/SocketAgent] socket_agent.go:90: Agent terminated
[44d1209ef7cdd38e/TLSAgent] tls_agent.go:140: Agent terminated
[44d1209ef7cdd38e/AckAgent] ack_agent.go:83: Agent terminated
[44d1209ef7cdd38e/SendingAgent] send_agent.go:200: Agent terminated
[44d1209ef7cdd38e/BufferAgent] buffer_agent.go:53: Agent terminated
[44d1209ef7cdd38e/FrameQueueAgent] frame_queue_agent.go:142: Agent terminated
[44d1209ef7cdd38e/ParsingAgent] parse_agent.go:156: Agent terminated
[44d1209ef7cdd38e/RTTAgent] rtt_agent.go:80: Agent terminated
[44d1209ef7cdd38e/StreamAgent] stream_agent.go:72: Agent terminated
[44d1209ef7cdd38e/HandshakeAgent] handshake_agent.go:166: Agent terminated
[1373f7b3f2060612/QLogAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/SocketAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/ParsingAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/BufferAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/TLSAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/AckAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/SendingAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/RecoveryAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/RTTAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/FrameQueueAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/FlowControlAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/StreamAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/ClosingAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/RecoveryAgent] recovery_agent.go:132: Agent terminated
[1373f7b3f2060612/HandshakeAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/HTTP3Agent] base_agent.go:49: Agent started
[1373f7b3f2060612/QPACKAgent] base_agent.go:49: Agent started
[1373f7b3f2060612/SendingAgent] send_agent.go:101: Chose 1RTT as new encryption level for BestAppData
[1373f7b3f2060612/SendingAgent] send_agent.go:101: Chose 1RTT as new encryption level for BestAppData
[1373f7b3f2060612/HandshakeAgent] handshake_agent.go:59: Sending first Initial packet
[1373f7b3f2060612/QPACKAgent] qpack_agent.go:158: Encoded 5 headers in 65 bytes, with 0 additional bytes on the encoder stream
[1373f7b3f2060612/HTTP3Agent] http3_agent.go:192: Sent a 65-byte long block of headers on stream 0
[1373f7b3f2060612/SendingAgent] send_agent.go:101: Chose 1RTT as new encryption level for BestAppData
picotls error code 513
[1373f7b3f2060612/SendingAgent] asm_amd64.s:522: Agent terminated
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x45d8c0]

goroutine 142 [running]:
github.com/QUIC-Tracker/quic-tracker.(*InitialPacket).Header(0x0, 0xc00046fd20, 0x8)
:1 +0x4e
github.com/QUIC-Tracker/quic-tracker/agents.(*SendingAgent).Run.func2(0xc000254320, 0xc0001611a0, 0xc0003c67e0, 0xc0003c6810, 0xc0003c6870, 0xc0003c6840, 0xc000174460, 0xc000318480, 0xc0004040fe, 0xc000161260, ...)
/go/src/github.com/QUIC-Tracker/quic-tracker/agents/send_agent.go:164 +0x74c
created by github.com/QUIC-Tracker/quic-tracker/agents.(*SendingAgent).Run
/go/src/github.com/QUIC-Tracker/quic-tracker/agents/send_agent.go:90 +0x59d
exit status 2`
@mpiraux
Copy link
Member

mpiraux commented Sep 15, 2022

picotls error code 513

That's a PTLS_ERROR_NO_MEMORY error. What's curious is that the new encryption level message as the 1RTT keys become available is printed three times. Do you have a pcap file + secrets to look into what were the exchanged packets? Or could you reproduce it to capture one?

@vranem1
Copy link
Author

vranem1 commented Sep 18, 2022

I don't have requested data for this exact run, because of the crash and I am not able to reproduce it. We see this crash once per a few tens of runs. Though the log before the crash looks exactly the same (including the tripled lines) as in case of ietf.akaquic.com, so the dumps should be similar to https://quic-tracker.info.ucl.ac.be/traces/20220918/6

@Karthikdasari0423
Copy link

@vranem1 Could you please share ,e the command you are using

@vranem1
Copy link
Author

vranem1 commented Dec 3, 2023 

   docker run -v "$bin_dir/my_hosts.txt:/h.txt" \
               -v "$PWD/logs:/logs" \
               -v "$traces/:/t/" \
               --user $(id -u):$(id -g) \
               --network=host \
                devqa/quictracker \
                /test_suite \
                  -hosts /h.txt \
                  -output /t/$cur_run \
                  -logs-directory /logs \
                  -parallel \
                  -debug

@Karthikdasari0423
Copy link

Thank you @vranem1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mpiraux @vranem1 @Karthikdasari0423