[asterisk-bugs] [JIRA] (ASTERISK-28562) SIP WSS message not processed until next frame arrives
Friendly Automation (JIRA)
noreply at issues.asterisk.org
Tue Jan 7 10:01:26 CST 2020
[ https://issues.asterisk.org/jira/browse/ASTERISK-28562?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=249257#comment-249257 ]
Friendly Automation commented on ASTERISK-28562:
------------------------------------------------
Change 13508 merged by Friendly Automation:
websocket: Consider pending SSL data when waiting for socket input
[https://gerrit.asterisk.org/c/asterisk/+/13508|https://gerrit.asterisk.org/c/asterisk/+/13508]
> SIP WSS message not processed until next frame arrives
> ------------------------------------------------------
>
> Key: ASTERISK-28562
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-28562
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Resources/res_http_websocket
> Affects Versions: 16.5.0
> Environment: Ubuntu 18.04, asterisk deployed in a docker container using host networking.
> Reporter: Robert Sutton
> Assignee: Sean Bright
> Labels: patch, pjsip
> Attachments: 0001-iostream.c-Consider-pending-SSL-data-during-fd-readi.patch
>
>
> I'm testing a new Flutter/Dart SIP stack (based on jssip) with Asterisk 16.5.1 (https://github.com/cloudwebrtc/dart-sip-ua)
> And after a few bug fixes it is working well except... I think we have an asterisk bug in the handling of messages for Secure Web Sockets (WSS).
> The problem is not apparent with Web Sockets (WS), it only occurs when using WSS, I think that it is probably due to packet fragmentation.
> The SIP client sends an ACK at 27.138078 immediately followed by an INVITE. Asterisk processes the ACK, but then goes to sleep (in ast_poll) between websocket frames waiting for the next frame even though it has already arrived as can be seen in the TCP dump. After about 10 seconds Asterisk sends an OPTIONS, which when the client receives this it replies with an ACK which finally wakes up asterisk and it processes the INVITE which was sent earlier as well as the ACK.
> As we believe that it is unlikely that ast_poll has a bug our theory is that ast_poll is reading from a pipe. At the other end of the pipe is the SSL stack. If the SSL stack reads the INVITE message from dart but for some reason (such as tcp fragmentation) doesn't read a full ssl frame. As such it can't decrypt the frame and therefore doesn't write the data to the pipe until the ssl stack sees another frame from the dart client. We are using the websockets implementation from dart core so we feel its unlikely to be a dart problem.
> We ran some test and found that we could remove the delay by adding 4K of random data to the end of the SIP INVITE. This seemed to be enough to cause SSL to read the entire frame.
> Its perhaps worth noting that adding 1K of data only helped sometimes
> We can also over come the problem by sending an empty websocket frame 100 ms after sending the invite.
> I've made some modifications to both the SIP client and Asterisk to help with diagnosing the problem.
> The SIP client now adds a timestamp to the end of every SIP message, for example in the line below from the asterisk logs we can see the the SIP message was sent 11 seconds before Asterisk processed it.
> {noformat}
> > [37.629721] SIP message generated and sent at: 17:22:26.849388
> {noformat}
> I've also added a number of ast_log's to Asterisk at the ERROR level as can be seen in the SIP dialog below. Note I've included the **diff** at the end to aid with correlating the line numbers of these logging messages.
> Below I've shown the order of the SIP messages, firstly in the order they appear in the Asterisk CLI, and then in the order they appear in TCP dump.
> the flow of SIP messages as shown in the Asterisk CLI, the out of sequence messages are in bold.
> INBOUND INVITE (MEDIA)
> OUNBOUND UNAUTHORIZED
> INBOUND ACK
> **OUTBOUND OPTIONS**
> **INBOUND INVITE (MEDIA)**
> INBOUND OPTIONS
> OUTBOUND INVITE (MEDIA)
> OUTBOUND INVITE (MEDIA)
> INBOUND ACK
> the flow of SIP messages as shown in the TCP dump
> INBOUND INVITE (MEDIA)
> OUNBOUND UNAUTHORIZED
> INBOUND ACK
> INBOUND INVITE (MEDIA)
> OUTBOUND OPTIONS
> INBOUND OPTIONS
> OUTBOUND INVITE (MEDIA)
> OUTBOUND INVITE (MEDIA)
> INBOUND ACK
> **PJSIP debug with additional logging.**
> {noformat}
> > [Oct 1 26] ERROR[78]: res_pjsip_transport_websocket.c:400 websocket_cb: websocket_cb before read
> > [26.965424] [Oct 1 26] ERROR[78]: res_http_websocket.c:573 __ast_websocket_read: waiting for frame header
> > [Oct 1 26] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [26.966066] [Oct 1 26] ERROR[78]: res_http_websocket.c:581 __ast_websocket_read: got frame header
> > [26.966118] [Oct 1 26] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [Oct 1 26] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [Oct 1 26] ERROR[78]: res_http_websocket.c:682 __ast_websocket_read: recieved payload size: 2264
> > [26.972168] [Oct 1 26] ERROR[78]: res_http_websocket.c:720 __ast_websocket_read: finished frame
> > [26.972197] [Oct 1 26] ERROR[78]: res_pjsip_transport_websocket.c:406 websocket_cb: websocket_cb got packet
> > [26.972222] [Oct 1 26] ERROR[78]: res_pjsip_transport_websocket.c:408 websocket_cb: websocket_cb before task
> > [26.972245] <--- Received SIP request (2201 bytes) from WSS:x.x.x.office:55604 --->
> > [26.972267] INVITE sip:7601 @pbx SIP/2.0
> > [26.972289] Via: SIP/2.0/WSS v2625374j25k.invalid;branch=z9hG4bK15772100250000000
> > [26.972311] Max-Forwards: 69
> > [26.972332] To: <sip:7601 @pbx>
> > [26.992696] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [26.992877] Call-ID: qujr6a3b88jlq5p4vkv2
> > [26.992927] CSeq: 5651 INVITE
> > [26.992971] Contact: <sip:74hb7in5 @v2625374j25k.invalid;transport=ws;ob>
> > [26.993015] Content-Type: application/sdp
> > [26.993060] Session-Expires: 120
> > [26.993102] Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
> > [26.993135] Supported: timer,ice,replaces,outbound
> > [26.993187] User-Agent: dart-sip-ua v0.0.1
> > [26.993231] Content-Length: 1613
> > [26.993274]
> > [26.993305] v=0
> > [26.994600] **** removed body to reduce size of forum post *****
> > [26.994622] SIP message generated and sent at: 17:22:26.694437
> > [26.994643]
> > [26.994664] [Oct 1 26] ERROR[78]: res_pjsip_transport_websocket.c:410 websocket_cb: websocket_cb after task
> > [26.994687] [Oct 1 26] ERROR[78]: res_pjsip_transport_websocket.c:415 websocket_cb: websocket_cb looping
> > <--- Transmitting SIP response (526 bytes) to WSS:x.x.x.office:55604 --->
> > [26.995216] SIP/2.0 401 Unauthorized
> > [26.995262] Via: SIP/2.0/WSS v2625374j25k.invalid;rport=55604;received=x.x.x.office;branch=z9hG4bK15772100250000000
> > [26.995306] Call-ID: qujr6a3b88jlq5p4vkv2
> > [26.995369] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [26.995416] To: <sip:7601 @pbx>;tag=z9hG4bK15772100250000000
> > [26.995459] CSeq: 5651 INVITE
> > [26.995502] WWW-Authenticate: removed
> > [26.995546] Server: Asterisk PBX 16.5.1
> > [26.995618] Content-Length: 0
> > [26.995661]
> > [26.995700]
> > [Oct 1 27] ERROR[78]: res_pjsip_transport_websocket.c:400 websocket_cb: websocket_cb before read
> > [27.105473] [Oct 1 27] ERROR[78]: res_http_websocket.c:573 __ast_websocket_read: waiting for frame header
> > [27.105540] [Oct 1 27] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [Oct 1 27] ERROR[78]: res_http_websocket.c:581 __ast_websocket_read: got frame header
> > [27.106763] [Oct 1 27] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [27.106810] [Oct 1 27] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [27.106853] [Oct 1 27] ERROR[78]: res_http_websocket.c:682 __ast_websocket_read: recieved payload size: 537
> > [27.106893] [Oct 1 27] ERROR[78]: res_http_websocket.c:720 __ast_websocket_read: finished frame
> > [27.106928] [Oct 1 27] ERROR[78]: res_pjsip_transport_websocket.c:406 websocket_cb: websocket_cb got packet
> > [27.107009] [Oct 1 27] ERROR[78]: res_pjsip_transport_websocket.c:408 websocket_cb: websocket_cb before task
> > <--- Received SIP request (474 bytes) from WSS:x.x.x.office:55604 --->
> > [27.138078] ACK sip:7601 @pbx SIP/2.0
> > [27.138116] Via: SIP/2.0/WSS v2625374j25k.invalid;branch=z9hG4bK15772100250000000
> > [27.138155] Max-Forwards: 69
> > [27.138183] To: <sip:7601 @pbx>;tag=z9hG4bK15772100250000000
> > [27.138205] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [27.138227] Call-ID: qujr6a3b88jlq5p4vkv2
> > [27.138248] CSeq: 5651 ACK
> > [27.138270] Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
> > [27.138292] Supported: outbound
> > [27.138313] User-Agent: dart-sip-ua v0.0.1
> > [27.138335] Content-Length: 0
> > [27.138365]
> > [27.138408]
> > [27.138441] SIP message generated and sent at: 17:22:26.828244
> > [27.138464]
> > [Oct 1 27] ERROR[78]: res_pjsip_transport_websocket.c:410 websocket_cb: websocket_cb after task
> > [27.138509] [Oct 1 27] ERROR[78]: res_pjsip_transport_websocket.c:415 websocket_cb: websocket_cb looping
> >
> >
> {noformat}
> THIS IS THE GAP WHERE ASTERISK IS ASLEEP
> {noformat}
> >
> > <--- Transmitting SIP request (456 bytes) to WSS:x.x.x.office:55604 --->
> > [37.552221] OPTIONS sip:74hb7in5 @x.x.x.office:55604;transport=ws SIP/2.0
> > [37.552248] Via: SIP/2.0/WSS x.x.x.pbx:8089;rport;branch=z9hG4bKPjffaf2009-639e-4f93-b647-e64beee427af;alias
> > [37.552271] From: <sip:8123 @pbx>;tag=bca2c6cd-236d-48a1-a180-44747a0a73b5
> > [37.552293] To: <sip:74hb7in5 @x.x.x.office>
> > [37.552315] Contact: <sip:8123 @pbx:5060;transport=ws>
> > [37.552336] Call-ID: d8815afc-3d56-4474-b81e-170870ababd1
> > [37.552357] CSeq: 57512 OPTIONS
> > [37.552379] Max-Forwards: 70
> > [37.552400] User-Agent: Asterisk PBX 16.5.1
> > [37.552421] Content-Length: 0
> > [37.552442]
> > [37.552463]
> > [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:400 websocket_cb: websocket_cb before read
> > [37.603823] [Oct 1 37] ERROR[78]: res_http_websocket.c:573 __ast_websocket_read: waiting for frame header
> > [37.603863] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.603914] [Oct 1 37] ERROR[78]: res_http_websocket.c:581 __ast_websocket_read: got frame header
> > [37.603951] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.603986] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.604023] [Oct 1 37] ERROR[78]: res_http_websocket.c:682 __ast_websocket_read: recieved payload size: 2514
> > [37.604059] [Oct 1 37] ERROR[78]: res_http_websocket.c:720 __ast_websocket_read: finished frame
> > [37.604098] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:406 websocket_cb: websocket_cb got packet
> > [37.604137] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:408 websocket_cb: websocket_cb before task
> > <--- Received SIP request (2451 bytes) from WSS:x.x.x.office:55604 --->
> > [37.627902] INVITE sip:7601 @pbx SIP/2.0
> > [37.627932] Via: SIP/2.0/WSS v2625374j25k.invalid;branch=z9hG4bK8869270160000000
> > [37.627961] Max-Forwards: 69
> > [37.627986] To: <sip:7601 @pbx>
> > [37.628008] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [37.628029] Call-ID: qujr6a3b88jlq5p4vkv2
> > [37.628051] CSeq: 5652 INVITE
> > [37.628085] Authorization: removed
> > [37.628129] Contact: <sip:74hb7in5 @v2625374j25k.invalid;transport=ws;ob>
> > [37.628155] Content-Type: application/sdp
> > [37.628176] Session-Expires: 120
> > [37.628198] Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
> > [37.628219] Supported: timer,ice,replaces,outbound
> > [37.628240] User-Agent: dart-sip-ua v0.0.1
> > [37.628261] Content-Length: 1613
> > [37.628283]
> > [37.628304] v=0
> > [37.629682] **** removed body to reduce size of forum post *****
> > [37.629721] SIP message generated and sent at: 17:22:26.849388
> > [37.629749]
> > [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:410 websocket_cb: websocket_cb after task
> > [37.629841] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:415 websocket_cb: websocket_cb looping
> > [37.629879] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:400 websocket_cb: websocket_cb before read
> > [37.629904] [Oct 1 37] ERROR[78]: res_http_websocket.c:573 __ast_websocket_read: waiting for frame header
> > [37.629927] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.629949] [Oct 1 37] ERROR[78]: res_http_websocket.c:581 __ast_websocket_read: got frame header
> > [37.629972] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.629994] [Oct 1 37] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [37.630016] [Oct 1 37] ERROR[78]: res_http_websocket.c:682 __ast_websocket_read: recieved payload size: 521
> > [37.630043] [Oct 1 37] ERROR[78]: res_http_websocket.c:720 __ast_websocket_read: finished frame
> > [37.630067] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:406 websocket_cb: websocket_cb got packet
> > [37.630090] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:408 websocket_cb: websocket_cb before task
> > <--- Received SIP response (458 bytes) from WSS:x.x.x.office:55604 --->
> > [37.630137] SIP/2.0 200 OK
> > [37.630171] Via: SIP/2.0/WSS x.x.x.pbx:8089;rport;branch=z9hG4bKPjffaf2009-639e-4f93-b647-e64beee427af;alias
> > [37.630212] To: <sip:74hb7in5 @x.x.x.office>;tag=eqdffq8i20
> > [37.630258] From: <sip:8123 @pbx>;tag=bca2c6cd-236d-48a1-a180-44747a0a73b5
> > [37.630289] Call-ID: d8815afc-3d56-4474-b81e-170870ababd1
> > [37.630311] CSeq: 57512 OPTIONS
> > [37.630333] Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
> > [37.630354] Accept: application/sdp, application/dtmf-relay
> > [37.630375] Supported: outbound
> > [37.630397] Content-Length: 0
> > [37.630481]
> > [37.630509]
> > [37.630531] SIP message generated and sent at: 17:22:37.353805
> > [37.630572]
> > [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:410 websocket_cb: websocket_cb after task
> > [37.630652] [Oct 1 37] ERROR[78]: res_pjsip_transport_websocket.c:415 websocket_cb: websocket_cb looping
> > <--- Transmitting SIP response (344 bytes) to WSS:x.x.x.office:55604 --->
> > [37.631952] SIP/2.0 100 Trying
> > [37.632006] Via: SIP/2.0/WSS v2625374j25k.invalid;rport=55604;received=x.x.x.office;branch=z9hG4bK8869270160000000
> > [37.632121] Call-ID: qujr6a3b88jlq5p4vkv2
> > [37.632215] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [37.632270] To: <sip:7601 @pbx>
> > [37.632374] CSeq: 5652 INVITE
> > [37.632474] Server: Asterisk PBX 16.5.1
> > [37.632516] Content-Length: 0
> > [37.632608]
> > [37.632677]
> >
> > [Oct 1 38] ERROR[30]: cdr.c:3335 ast_cdr_getvar: Unable to find CDR for channel PJSIP/8123-00000001
> > <--- Transmitting SIP response (1509 bytes) to WSS:x.x.x.office:55604 --->
> > [38.379670] SIP/2.0 183 Session Progress
> > [38.379699] Via: SIP/2.0/WSS v2625374j25k.invalid;rport=55604;received=x.x.x.office;branch=z9hG4bK8869270160000000
> > [38.379722] Call-ID: qujr6a3b88jlq5p4vkv2
> > [38.379756] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [38.379794] To: <sip:7601 @pbx>;tag=39149121-1984-4008-8c81-a3ca7e6461e4
> > [38.379819] CSeq: 5652 INVITE
> > [38.379841] Server: Asterisk PBX 16.5.1
> > [38.379862] Contact: <sip:x.x.x.pbx:8089;transport=ws>
> > [38.379883] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
> > [38.379905] Content-Type: application/sdp
> > [38.379926] Content-Length: 921
> > [38.379947]
> > [38.379968] v=0
> > [38.381139] **** removed body to reduce size of forum post *****
> > <--- Transmitting SIP response (1595 bytes) to WSS:x.x.x.office:55604 --->
> > [38.385830] SIP/2.0 200 OK
> > [38.385851] Via: SIP/2.0/WSS v2625374j25k.invalid;rport=55604;received=x.x.x.office;branch=z9hG4bK8869270160000000
> > [38.385879] Call-ID: qujr6a3b88jlq5p4vkv2
> > [38.385895] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [38.385922] To: <sip:7601 @pbx>;tag=39149121-1984-4008-8c81-a3ca7e6461e4
> > [38.385939] CSeq: 5652 INVITE
> > [38.385964] Server: Asterisk PBX 16.5.1
> > [38.385984] Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
> > [38.386006] Contact: <sip:x.x.x.pbx:8089;transport=ws>
> > [38.386029] Supported: 100rel, timer, replaces, norefersub
> > [38.386053] Session-Expires: 120;refresher=uac
> > [38.386077] Require: timer
> > [38.386102] Content-Type: application/sdp
> > [38.386123] Content-Length: 921
> > [38.386142]
> > [38.386169] v=0
> > [38.392284] **** removed body to reduce size of forum post *****
> > [Oct 1 38] ERROR[78]: res_pjsip_transport_websocket.c:400 websocket_cb: websocket_cb before read
> > [38.483615] [Oct 1 38] ERROR[78]: res_http_websocket.c:573 __ast_websocket_read: waiting for frame header
> > [38.483686] [Oct 1 38] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [Oct 1 38] ERROR[78]: res_http_websocket.c:581 __ast_websocket_read: got frame header
> > [38.484106] [Oct 1 38] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [38.484156] [Oct 1 38] WARNING[78]: res_http_websocket.c:514 ws_safe_read: entering ws_safe_read
> > [38.484202] [Oct 1 38] ERROR[78]: res_http_websocket.c:682 __ast_websocket_read: recieved payload size: 545
> > [38.484249] [Oct 1 38] ERROR[78]: res_http_websocket.c:720 __ast_websocket_read: finished frame
> > [38.484293] [Oct 1 38] ERROR[78]: res_pjsip_transport_websocket.c:406 websocket_cb: websocket_cb got packet
> > [38.484338] [Oct 1 38] ERROR[78]: res_pjsip_transport_websocket.c:408 websocket_cb: websocket_cb before task
> > <--- Received SIP request (482 bytes) from WSS:x.x.x.office:55604 --->
> > [38.484639] ACK sip:x.x.x.pbx:8089;transport=ws SIP/2.0
> > [38.484694] Via: SIP/2.0/WSS v2625374j25k.invalid;branch=z9hG4bK18422844440000000
> > [38.484736] Max-Forwards: 69
> > [38.484777] To: <sip:7601 @pbx>;tag=39149121-1984-4008-8c81-a3ca7e6461e4
> > [38.484818] From: "8123" <sip:8123 @pbx>;tag=176414r3g3
> > [38.484861] Call-ID: qujr6a3b88jlq5p4vkv2
> > [38.484900] CSeq: 5652 ACK
> > [38.484941] Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
> > [38.484983] Supported: outbound
> > [38.485023] User-Agent: dart-sip-ua v0.0.1
> > [38.485062] Content-Length: 0
> > [38.485102]
> > [38.485140]
> > [38.485179] SIP message generated and sent at: 17:22:38.231809
> > [38.485221]
> {noformat}
> **TCP DUMP with some annotations**
> I have attempted to correlate the packets to the SIP messages
> {noformat}
> INBOUND INVITE
> 26.964445 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 12863:12900, ack 10157, win 576, options [nop,nop,TS val 29190351 ecr 1099012739], length 37
> 26.968637 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 12900:14360, ack 10157, win 576, options [nop,nop,TS val 29190352 ecr 1099012739], length 1460
> * 26.968667 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [.], ack 14360, win 550, options [nop,nop,TS val 1099015698 ecr 29190351], length 0
> 26.968732 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 14360:15222, ack 10157, win 576, options [nop,nop,TS val 29190352 ecr 1099012739], length 862
> OUTBOUND UNAUTHORIZED
> 26.993267 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 10157:10716, ack 15222, win 573, options [nop,nop,TS val 1099015723 ecr 29190352], length 559
> * 27.027392 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 10716, win 599, options [nop,nop,TS val 29190367 ecr 1099015723], length 0
> INBOUND ACK
> 27.104493 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 15222:15361, ack 10716, win 599, options [nop,nop,TS val 29190386 ecr 1099015723], length 139
> INBOUND INVITE (MEDIA)
> 27.104556 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 15361:16821, ack 10716, win 599, options [nop,nop,TS val 29190386 ecr 1099015723], length 1460
> * 27.104582 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [.], ack 16821, win 618, options [nop,nop,TS val 1099015834 ecr 29190386], length 0
> 27.105570 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], seq 16821:18269, ack 10716, win 599, options [nop,nop,TS val 29190386 ecr 1099015723], length 1448
> 27.105588 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 18269:18318, ack 10716, win 599, options [nop,nop,TS val 29190387 ecr 1099015723], length 49
> *27.105597 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [.], ack 18318, win 641, options [nop,nop,TS val 1099015835 ecr 29190386], length 0
> {noformat}
> 8 second gap
> {noformat}
> OUTBOUND OPTIONS
> 35.342972 IP x.x.x.pbx.8089 > x.x.x.office.56090: Flags [P.], seq 3688:3723, ack 724, win 243, options [nop,nop,TS val 1099024072 ecr 29187267], length 35
> 35.343030 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 10716:10751, ack 18318, win 641, options [nop,nop,TS val 1099024073 ecr 29190386], length 35
> 35.343056 IP x.x.x.pbx.8089 > x.x.x.office.55434: Flags [P.], seq 6209:6244, ack 4881, win 316, options [nop,nop,TS val 1099024073 ecr 29174194], length 35
> *35.360274 IP x.x.x.office.56090 > x.x.x.pbx.8089: Flags [.], ack 3723, win 325, options [nop,nop,TS val 29192450 ecr 1099024072], length 0
> *35.377934 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 10751, win 599, options [nop,nop,TS val 29192454 ecr 1099024073], length 0
> *35.407968 IP x.x.x.office.55434 > x.x.x.pbx.8089: Flags [.], ack 6244, win 438, options [nop,nop,TS val 29192460 ecr 1099024073], length 0
> OUTBOUND INVITE (MEDIA)
> 37.551828 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 10751:11240, ack 18318, win 641, options [nop,nop,TS val 1099026281 ecr 29192454], length 489
> *37.589318 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 11240, win 621, options [nop,nop,TS val 29193007 ecr 1099026281], length 0
> 37.602325 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 18318:18876, ack 11240, win 621, options [nop,nop,TS val 29193011 ecr 1099026281], length 558
> 37.628046 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 11240:11617, ack 18876, win 663, options [nop,nop,TS val 1099026358 ecr 29193011], length 377
> *37.704678 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 11617, win 644, options [nop,nop,TS val 29193036 ecr 1099026358], length 0
> OUTBOUND INVITE (MEDIA)
> 38.379851 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 11617:13159, ack 18876, win 663, options [nop,nop,TS val 1099027109 ecr 29193036], length 1542
> 38.385962 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [P.], seq 13159:14787, ack 18876, win 663, options [nop,nop,TS val 1099027116 ecr 29193036], length 1628
> *38.421608 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 13159, win 668, options [nop,nop,TS val 29193214 ecr 1099027109], length 0
> *38.421648 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [.], ack 14787, win 694, options [nop,nop,TS val 29193215 ecr 1099027116], length 0
> INBOUND ACK
> 38.481815 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 18876:18913, ack 14787, win 694, options [nop,nop,TS val 29193231 ecr 1099027116], length 37
> 38.481888 IP x.x.x.office.55604 > x.x.x.pbx.8089: Flags [P.], seq 18913:19487, ack 14787, win 694, options [nop,nop,TS val 29193231 ecr 1099027116], length 574
> *38.482521 IP x.x.x.pbx.8089 > x.x.x.office.55604: Flags [.], ack 19487, win 686, options [nop,nop,TS val 1099027212 ecr 29193231], length 0
> {noformat}
> **Diff of the code changes I made to add logging**
> {noformat}
> diff --git a/res/res_http_websocket.c b/res/res_http_websocket.c
> index a44f601..7a1b965 100644
> --- a/res/res_http_websocket.c
> +++ b/res/res_http_websocket.c
> @@ -511,6 +511,7 @@ static inline int ws_safe_read(struct ast_websocket *session, char *buf, size_t
> return -1;
> }
>
> + ast_log(LOG_WARNING, "entering ws_safe_read\n");
> for (;;) {
> rlen = ast_iostream_read(session->stream, rbuf, xlen);
> if (rlen != xlen) {
> @@ -569,12 +570,16 @@ int AST_OPTIONAL_API_NAME(ast_websocket_read)(struct ast_websocket *session, cha
> *payload = NULL;
> *payload_len = 0;
> *fragmented = 0;
> + ast_log(LOG_ERROR, "waiting for frame header\n");
>
> if (ws_safe_read(session, &buf[0], MIN_WS_HDR_SZ, opcode)) {
> return -1;
> }
> frame_size += MIN_WS_HDR_SZ;
>
> +
> + ast_log(LOG_ERROR, "got frame header\n");
> +
> /* ok, now we have the first 2 bytes, so we know some flags, opcode and payload length (or whether payload length extension will be required) */
> *opcode = buf[0] & 0xf;
> *payload_len = buf[1] & 0x7f;
> @@ -660,6 +665,12 @@ int AST_OPTIONAL_API_NAME(ast_websocket_read)(struct ast_websocket *session, cha
> session->payload = new_payload;
> memcpy((session->payload + session->payload_len), (*payload), (*payload_len));
> session->payload_len += *payload_len;
> + char format[100];
> + sprintf(format,"%%%lds\n",*payload_len);
> + char temp[32768];
> + sprintf(temp,format,*payload);
> + // ast_log(LOG_ERROR,format,*payload);
> + ast_log(LOG_ERROR,"recieved payload size: %ld\n",*payload_len);//,strlen(temp));
> } else if (!session->payload_len && session->payload) {
> ast_free(session->payload);
> session->payload = NULL;
> @@ -667,6 +678,8 @@ int AST_OPTIONAL_API_NAME(ast_websocket_read)(struct ast_websocket *session, cha
>
> if (!fin && session->reconstruct && (session->payload_len < session->reconstruct)) {
> /* If this is not a final message we need to defer returning it until later */
> + ast_log(LOG_ERROR, "continuation\n");
> +
> if (*opcode != AST_WEBSOCKET_OPCODE_CONTINUATION) {
> session->opcode = *opcode;
> }
> @@ -694,6 +707,8 @@ int AST_OPTIONAL_API_NAME(ast_websocket_read)(struct ast_websocket *session, cha
> ast_websocket_close(session, 1003);
> }
>
> +
> + ast_log(LOG_ERROR, "finished frame\n");
> return 0;
> }
>
> @@ -1396,6 +1411,7 @@ int AST_OPTIONAL_API_NAME(ast_websocket_read_string)
> int fragmented = 1;
>
> while (fragmented) {
> + ast_log(LOG_ERROR,"in ast_websocket_read_string\n");
> if (ast_websocket_read(ws, &payload, &payload_len,
> &opcode, &fragmented)) {
> ast_log(LOG_ERROR, "Client WebSocket string read - "
> diff --git a/res/res_pjsip_transport_websocket.c b/res/res_pjsip_transport_websocket.c
> index 8bc078b..8755396 100644
> --- a/res/res_pjsip_transport_websocket.c
> +++ b/res/res_pjsip_transport_websocket.c
> @@ -392,23 +392,30 @@ static void websocket_cb(struct ast_websocket *session, struct ast_variable *par
> transport = create_data.transport;
> read_data.transport = transport;
>
> + ast_log(LOG_ERROR,"websocket_cb start\n");
> while (ast_wait_for_input(ast_websocket_fd(session), -1) > 0) {
> enum ast_websocket_opcode opcode;
> int fragmented;
>
> + ast_log(LOG_ERROR,"websocket_cb before read\n");
> if (ast_websocket_read(session, &read_data.payload, &read_data.payload_len, &opcode, &fragmented)) {
> break;
> }
>
> if (opcode == AST_WEBSOCKET_OPCODE_TEXT || opcode == AST_WEBSOCKET_OPCODE_BINARY) {
> + ast_log(LOG_ERROR,"websocket_cb got packet\n");
> if (read_data.payload_len) {
> + ast_log(LOG_ERROR,"websocket_cb before task\n");
> ast_sip_push_task_wait_serializer(serializer, transport_read, &read_data);
> + ast_log(LOG_ERROR,"websocket_cb after task\n");
> }
> } else if (opcode == AST_WEBSOCKET_OPCODE_CLOSE) {
> break;
> }
> + ast_log(LOG_ERROR,"websocket_cb looping\n");
> }
>
> + ast_log(LOG_ERROR,"websocket_cb exiting\n");
> ast_sip_push_task_wait_serializer(serializer, transport_shutdown, transport);
>
> ast_taskprocessor_unreference(serializer);
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list