ASTERISK-28562: SIP WSS message not processed until next frame arrives

[Home]

Summary: ASTERISK-28562: SIP WSS message not processed until next frame arrives

Reporter: Robert Sutton (rsutton@noojee.com.au) Labels: patch pjsip

Date Opened: 2019-10-02 18:34:12 Date Closed: 2020-01-07 10:00:04.000-0600

Priority: Major Regression? No

Status: Closed/Complete Components: Resources/res_http_websocket

Versions: 16.5.0 Frequency of
Occurrence Frequent

Related
Issues:

Environment: Ubuntu 18.04, asterisk deployed in a docker container using host networking. Attachments: ( 0) 0001-iostream.c-Consider-pending-SSL-data-during-fd-readi.patch

Description: 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}

Comments: By: Asterisk Team (asteriskteam) 2019-10-02 18:34:13.552-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Sean Bright (seanbright) 2019-10-03 18:44:21.148-0500

Is there any chance you could publish a git repository of a web project that would help reproduce this?
By: Robert Sutton (rsutton@noojee.com.au) 2019-10-03 18:50:52.964-0500

This is an android/IOS project, I could fairly easily provide and APK (android package). Is that useful?
By: Sean Bright (seanbright) 2019-10-03 18:54:01.578-0500

Potentially. Can an APK be run in an emulator? Can you reproduce in an emulator?
By: Robert Sutton (rsutton@noojee.com.au) 2019-10-03 23:42:41.723-0500

Yes an APK can be run in an emulator, and yes it is reproducible in the emulator.

Here is a link to the APK in my google drive https://drive.google.com/file/d/1BCx9UAsczCyDImfcsCm8Z_ryWqlxprlP/view?usp=sharing

Here is a link to instructions on how to install the app on the emulator https://mobikul.com/install-external-app-android-emulator/

How to reproduce:
{quote}
On launch, open the menu in the top left and click account, fill out your server details and click register. The "Register Status" at the top should change to "registered" if successful.

Then click back, clear the text field at the top and enter an extension number to dial and click the green dial button.

The screen immediately transitions to "connecting" and after between 0 and 15 seconds the call will establish.
{quote}

The problem is evident about 80% of the time ranging between 4 and 15 seconds.
By: Sean Bright (seanbright) 2019-10-04 08:52:46.747-0500

[~rsutton@noojee.com.au], can you provide a version that reproduces the problem that does _not_ add the {{SIP message generated...}} at the end of each message?
By: Robert Sutton (rsutton@noojee.com.au) 2019-10-06 19:32:14.159-0500

Here is a fresh build without the extra message.

https://drive.google.com/file/d/1naJnczsy0xpet2Fxqkv2wk4FlTMa46ii/view?usp=sharing

Thanks.
By: Sean Bright (seanbright) 2019-11-26 13:46:08.891-0600

[~rsutton@noojee.com.au], I've attached a potential fix in [^0001-iostream.c-Consider-pending-SSL-data-during-fd-readi.patch]. Could you take it for a spin and let us know if it resolves the issue you were experiencing?

{noformat}
cd /path/to/asterisk/16/source
patch -p1 < /path/to/0001-iostream.c-Consider-pending-SSL-data-during-fd-readi.patch
{noformat}

By: Robert Sutton (rsutton@noojee.com.au) 2019-11-26 20:55:22.576-0600

Thanks Sean,

I've done back to back testing of both the unpatched and patched build.

I'm happy to report that the patch fixes the issue.

Robert.
By: Robert Sutton (rsutton@noojee.com.au) 2019-11-26 20:57:17.222-0600

just to be clear - the patch fixed the problem and the problem was easily reproducible without the patch
By: Friendly Automation (friendly-automation) 2020-01-07 10:00:05.514-0600

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]
By: Friendly Automation (friendly-automation) 2020-01-07 10:03:13.295-0600

Change 13541 merged by Friendly Automation:
websocket: Consider pending SSL data when waiting for socket input

[https://gerrit.asterisk.org/c/asterisk/+/13541|https://gerrit.asterisk.org/c/asterisk/+/13541]
By: Friendly Automation (friendly-automation) 2020-01-07 10:13:34.970-0600

Change 13540 merged by George Joseph:
websocket: Consider pending SSL data when waiting for socket input

[https://gerrit.asterisk.org/c/asterisk/+/13540|https://gerrit.asterisk.org/c/asterisk/+/13540]