search

drachtio / drachtio-server

A SIP call processing server that can be controlled via nodejs applications
https://drachtio.org
MIT License
233 stars 90 forks source link

reInvite after 491 response is not proxied #318

Open rhondahollis opened 8 months ago

rhondahollis commented 8 months ago

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