reInvite after 491 response is not proxied
rhondahollis opened this issue · 0 comments
When Drachtio receives a resend of a reInvite that had originally resulted in a 491 Request Pending, the INVITE is not sent on to the other leg. The last thing I see in the log for the handling of this reInvite is:
2023-11-16 19:24:35.105989 SipDialog::setSessionTimer: 98833900-ff58-123c-19bc-0050569252d2 Session expires has been set to 90 seconds and refresher is them
Full log has been sent to you.
023-11-16 19:24:33.919306 recv 2297 bytes from wss/[10.x.x.x]:47890 at 19:24:33.919051:
INVITE sip:10.x.x.x:8443;transport=wss SIP/2.0
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK6568772
Max-Forwards: 69
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8476 INVITE
Contact: sip:tc21259l@of4tbtaiaa61.invalid;transport=ws
Content-Type: application/sdp
Session-Expires: 90;refresher=uac
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
Content-Length: 1604
v=0
o=- 6673137049813337921 3 IN IP4 127.0.0.1
s=-
t=0 0
a=extmap-allow-mixed
a=msid-semantic: WMS 4b1f370e-80f1-4aa5-8edc-910fec96398c
a=group:BUNDLE 1
m=audio 59474 UDP/TLS/RTP/SAVPF 0 111 63 9 8 13 110 126
c=IN IP4 10.x.x.x
a=rtpmap:0 PCMU/8000
a=rtpmap:111 opus/48000/2
a=rtpmap:63 red/48000/2
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:126 telephone-event/8000
a=fmtp:111 minptime=10;useinbandfec=1
a=fmtp:63 111/111
a=rtcp:9 IN IP4 0.0.0.0
a=rtcp-fb:111 transport-cc
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=setup:actpass
a=mid:1
a=msid:4b1f370e-80f1-4aa5-8edc-910fec96398c 45ec95c4-242e-44f0-a0f8-96c3915043df
a=sendonly
a=ice-ufrag:RXun
a=ice-pwd:ujPqWZLHEwL42Rw7nDe6jSpU
a=fingerprint:sha-256 77:46:11:18:8D:A6:03:D4:C1:2A:95:BC:98:EE:2D:21:73:68:52:5C:7E:36:FB:50:D5:39:5D:19:99:0F:65:17
a=candidate:3602474049 1 udp 2122260223 10.x.x.x 59474 typ host generation 0 network-id 1
a=candidate:2111712589 1 udp 2122194687 192.x.x.x 49939 typ host generation 0 network-id 2 network-cost 10
a=candidate:84138425 1 udp 2122129151 10.x.x.x 62696 typ host generation 0 network-id 3 network-cost 50
a=ice-options:trickle
a=ssrc:3764336703 cname:CdLFdL9WWwV95Grj
a=ssrc:3764336703 msid:4b1f370e-80f1-4aa5-8edc-910fec96398c 45ec95c4-242e-44f0-a0f8-96c3915043df
a=rtcp-mux
2023-11-16 19:24:33.919805 send 340 bytes to wss/[10.x.x.x]:47890 at 19:24:33.919620:
SIP/2.0 100 Trying
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK6568772;received=10.x.x.x;rport=47890
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8476 INVITE
Content-Length: 0
2023-11-16 19:24:33.928630 send 1056 bytes to tcp/[10.x.x.x]:55311 at 19:24:33.928444:
INVITE sip:sipp@10.x.x.x:55311;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 10.x.x.x;branch=z9hG4bKtKKUSe96paBFc
Max-Forwards: 70
From: sut sip:7659@10.x.x.x:5060;tag=8gmX46BBrtj5H
To: sipp sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
Call-ID: 1-66175@10.x.x.x
CSeq: 2 INVITE
Contact: sip:10.x.x.x:5060;transport=tcp
Allow: INVITE, ACK, CANCEL, BYE, UPDATE, MESSAGE, OPTIONS, REFER, INFO, NOTIFY
Content-Type: application/sdp
Content-Length: 541
v=0
o=- 6673137049813337921 3 IN IP4 10.103.114.26
s=-
t=0 0
a=extmap-allow-mixed
m=audio 17040 RTP/AVP 0 9 8 126
c=IN IP4 10.103.114.26
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=mid:1
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:126 telephone-event/8000
a=sendonly
a=rtcp:17041
2023-11-16 19:24:34.013113 recv 326 bytes from tcp/[10.x.x.x]:55311 at 19:24:34.013013:
SIP/2.0 491 Request Pending
Via: SIP/2.0/TCP 10.x.x.x;branch=z9hG4bKtKKUSe96paBFc
From: sut sip:7659@10.x.x.x:5060;tag=8gmX46BBrtj5H
To: sipp sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001;tag=66175SIPpTag011
Call-ID: 1-66175@10.x.x.x
CSeq: 2 INVITE
Content-Length: 0
2023-11-16 19:24:34.013508 send 367 bytes to tcp/[10.x.x.x]:55311 at 19:24:34.013382:
ACK sip:sipp@10.x.x.x:55311;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 10.x.x.x;branch=z9hG4bKtKKUSe96paBFc
Max-Forwards: 70
From: sut sip:7659@10.x.x.x:5060;tag=8gmX46BBrtj5H
To: sipp sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001;tag=66175SIPpTag011
Call-ID: 1-66175@10.x.x.x
CSeq: 2 ACK
Content-Length: 0
2023-11-16 19:24:34.017289 send 399 bytes to wss/[10.x.x.x]:47890 at 19:24:34.017144:
SIP/2.0 491 Request Pending
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK6568772;received=10.x.x.x;rport=47890
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8476 INVITE
Contact: sips:10.x.x.x:8443;transport=wss
Content-Length: 0
2023-11-16 19:24:34.085163 recv 540 bytes from wss/[10.x.x.x]:47890 at 19:24:34.085114:
ACK sip:10.x.x.x:8443;transport=wss SIP/2.0
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK6568772
Max-Forwards: 69
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8476 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
Content-Length: 0
2023-11-16 19:24:35.105743 recv 2297 bytes from wss/[10.x.x.x]:47890 at 19:24:35.105647:
INVITE sip:10.x.x.x:8443;transport=wss SIP/2.0
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK7807801
Max-Forwards: 69
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8477 INVITE
Contact: sip:tc21259l@of4tbtaiaa61.invalid;transport=ws
Content-Type: application/sdp
Session-Expires: 90;refresher=uac
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: timer,ice,replaces,outbound
Content-Length: 1604
v=0
o=- 6673137049813337921 3 IN IP4 127.0.0.1
s=-
t=0 0
a=extmap-allow-mixed
a=msid-semantic: WMS 4b1f370e-80f1-4aa5-8edc-910fec96398c
a=group:BUNDLE 1
m=audio 59474 UDP/TLS/RTP/SAVPF 0 111 63 9 8 13 110 126
c=IN IP4 10.x.x.x
a=rtpmap:0 PCMU/8000
a=rtpmap:111 opus/48000/2
a=rtpmap:63 red/48000/2
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:126 telephone-event/8000
a=fmtp:111 minptime=10;useinbandfec=1
a=fmtp:63 111/111
a=rtcp:9 IN IP4 0.0.0.0
a=rtcp-fb:111 transport-cc
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=setup:actpass
a=mid:1
a=msid:4b1f370e-80f1-4aa5-8edc-910fec96398c 45ec95c4-242e-44f0-a0f8-96c3915043df
a=sendonly
a=ice-ufrag:RXun
a=ice-pwd:ujPqWZLHEwL42Rw7nDe6jSpU
a=fingerprint:sha-256 77:46:11:18:8D:A6:03:D4:C1:2A:95:BC:98:EE:2D:21:73:68:52:5C:7E:36:FB:50:D5:39:5D:19:99:0F:65:17
a=candidate:3602474049 1 udp 2122260223 10.x.x.x 59474 typ host generation 0 network-id 1
a=candidate:2111712589 1 udp 2122194687 192.x.x.x 49939 typ host generation 0 network-id 2 network-cost 10
a=candidate:84138425 1 udp 2122129151 10.x.x.x 62696 typ host generation 0 network-id 3 network-cost 50
a=ice-options:trickle
a=ssrc:3764336703 cname:CdLFdL9WWwV95Grj
a=ssrc:3764336703 msid:4b1f370e-80f1-4aa5-8edc-910fec96398c 45ec95c4-242e-44f0-a0f8-96c3915043df
a=rtcp-mux
2023-11-16 19:24:35.105787 tport.c:3108 tport_deliver() tport_deliver(0x55e33c7b0000): msg 0x55e33b6c8000 (2297 bytes) from wss/10.x.x.x:47890 next=(nil)
2023-11-16 19:24:35.105792 tport.c:1181 tport_ref() tport_ref(0x55e33c7b0000): refcount is now 5
2023-11-16 19:24:35.105798 nta.c:3060 agent_recv_request() nta: received INVITE sip:10.x.x.x:8443;transport=wss SIP/2.0 (CSeq 8477)
2023-11-16 19:24:35.105807 nta.c:3360 agent_check_request_via() nta: Via check: received=10.x.x.x
2023-11-16 19:24:35.105817 nta.c:3243 agent_recv_request() nta: INVITE (8477) going to existing leg
2023-11-16 19:24:35.105828 nta.c:1428 set_timeout() nta: timer shortened to 2000 ms
2023-11-16 19:24:35.105835 tport.c:1181 tport_ref() tport_ref(0x55e33c7b0000): refcount is now 6
2023-11-16 19:24:35.105850 SipDialogController::processRequestInsideDialog: INVITE irq 0x55e33c895cc0
2023-11-16 19:24:35.105874 tport.c:3343 tport_tsend() tport_tsend(0x55e33c7b0000) tpn = WSS/10.x.x.x:47890
2023-11-16 19:24:35.105885 tport_type_ws.c:310 tport_send_stream_ws() tport_ws_writevec: vec 0x55e33c7b01f0 0x55e33b6bbc00 116 (0)
2023-11-16 19:24:35.105889 tport_type_ws.c:310 tport_send_stream_ws() tport_ws_writevec: vec 0x55e33c7b01f0 0x55e33bf4d4bb 82 (0)
2023-11-16 19:24:35.105892 tport_type_ws.c:310 tport_send_stream_ws() tport_ws_writevec: vec 0x55e33c7b01f0 0x55e33bf4d484 55 (0)
2023-11-16 19:24:35.105895 tport_type_ws.c:310 tport_send_stream_ws() tport_ws_writevec: vec 0x55e33c7b01f0 0x55e33bf4d50d 66 (0)
2023-11-16 19:24:35.105898 tport_type_ws.c:310 tport_send_stream_ws() tport_ws_writevec: vec 0x55e33c7b01f0 0x55e33b6bbc74 21 (0)
2023-11-16 19:24:35.105944 tport.c:3592 tport_send_msg() tport_vsend returned 340
2023-11-16 19:24:35.105963 send 340 bytes to wss/[10.x.x.x]:47890 at 19:24:35.105883:
SIP/2.0 100 Trying
Via: SIP/2.0/WSS of4tbtaiaa61.invalid;branch=z9hG4bK7807801;received=10.x.x.x;rport=47890
From: sip:7659@10.x.x.x:5060;tag=piei9gnbi0
To: sip:sipp@10.x.x.x:55311;tag=66175SIPpTag001
Call-ID: 98833900-ff58-123c-19bc-0050569252d2
CSeq: 8477 INVITE
Content-Length: 0
2023-11-16 19:24:35.105978 tport.c:2363 tport_set_secondary_timer() tport(0x55e33c7b0000): reset timer
2023-11-16 19:24:35.105982 nta.c:6985 incoming_reply() nta: sent 100 Trying for INVITE (8477)
2023-11-16 19:24:35.105985 SipDialogController::processRequestInsideDialog - canceling session expires timer due to re-invite
2023-11-16 19:24:35.105989 SipDialog::setSessionTimer: 98833900-ff58-123c-19bc-0050569252d2 Session expires has been set to 90 seconds and refresher is them
2023-11-16 19:24:35.106000 tport.c:1181 tport_ref() tport_ref(0x55e33c7b0000): refcount is now 7
2023-11-16 19:24:35.106004 tport.c:1194 tport_unref() tport_unref(0x55e33c7b0000): refcount is now 6
2023-11-16 19:24:35.106013 ClientController::addNetTransaction: transactionId b9042453-801e-46a8-8ad1-524727b851c8; size: 222
2023-11-16 19:24:35.106025 SipDialogController::addIncomingRequestTransaction - adding transactionId b9042453-801e-46a8-8ad1-524727b851c8 for irq:0x55e33c895cc0
2023-11-16 19:24:35.106032 tport.c:1194 tport_unref() tport_unref(0x55e33c7b0000): refcount is now 5
2023-11-16 19:24:35.106035 tport.c:2363 tport_set_secondary_timer() tport(0x55e33c7b0000): reset timer
2023-11-16 19:24:35.106104 Client::write_handler - wrote 2532 bytes: system:0
2023-11-16 19:24:35.880588 tport.c:2845 tport_wakeup() tport_wakeup(0x55e33c9c0000): events IN
2023-11-16 19:24:35.880659 tport.c:2949 tport_recv_event() tport_recv_event(0x55e33c9c0000)
2023-11-16 19:24:35.880736 tport.c:3290 tport_recv_iovec() tport_recv_iovec(0x55e33c9c0000) msg 0x55e33b6ba000 from (wss/10.x.x.x:50392) has 2 bytes, veclen = 1
2023-11-16 19:24:35.880768 tport.c:3108 tport_deliver() tport_deliver(0x55e33c9c0000): bad msg 0x55e33b6ba000 (2 bytes) from wss/10.x.x.x:50392 next=(nil)
2023-11-16 19:24:35.880787 tport.c:1181 tport_ref() tport_ref(0x55e33c9c0000): refcount is now 2
2023-11-16 19:24:35.880836 tport.c:1194 tport_unref() tport_unref(0x55e33c9c0000): refcount is now 1
2023-11-16 19:24:35.880854 tport.c:2363 tport_set_secondary_timer() tport(0x55e33c9c0000): reset timer
2023-11-16 19:24:37.105979 nta.c:1376 agent_timer() nta: timer set next to 24628 ms