drachtio-server
drachtio-server copied to clipboard
Published
20 hours ago •
drachtio
drachtio
Subsequent INVITEs to FSMRF Fail
I have a weird issue: I recently updated my drachtio-server docker image (at your recommendation), but ever since then when I try to connect to an MRF server for a 2nd time to the same user, the INVITE just hangs and eventually fails with a SIP 408 timeout (issued by drahctio). Subsequent retries do the same thing. If I restart Drachtio, things work again (once).
I downgraded all the way back to drachtio-server v0.8.8 and the problem goes away (but no version after that works).
Perhaps you have an idea of what might be causing this? If not I can begin collecting more logs, but I do have 2 examples below. Bad first, then good (they are kinda big).
**NOT WORKING (v0.8.11-16) **
response from rtpengine to offer {"sdp":"v=0\r\no=- 4788793608 61235 IN IP4 104.131.19.169\r\ns=qvfyufl\r\nc=IN IP4 104.131.19.169\r\nt=0 0\r\nm=audio 20286 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20287\r\na=ptime:20\r\nm=audio 20330 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20331\r\na=ptime:20\r\nm=video 20360 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20361\r\nm=video 20392 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20393\r\n","result":"ok"}
{"level":30, "time": "2022-03-23T01:44:09.408Z","pid":1316316,"hostname":"east1","callId":"325713D374CE80D5756D68FB989AD5DB6A2A3DDC","msg":"Creating FreeSWITCH Broadcast endpoint."}
2022-03-23T01:44:09.409Z drachtio:agent options: {"uri":"sip:[email protected]:5038","method":"INVITE","headers":{"User-Agent":"drachtio-fsmrf:2931d499-e626-42e9-bd47-25717434a0a8","X-esl-outbound":"104.131.19.169:8099"},"body":"v=0\r\no=- 4788793608 61235 IN IP4 104.131.19.169\r\ns=qvfyufl\r\nc=IN IP4 104.131.19.169\r\nt=0 0\r\nm=audio 20286 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20287\r\na=ptime:20\r\nm=audio 20330 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20331\r\na=ptime:20\r\nm=video 20360 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20361\r\nm=video 20392 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20393\r\n"}
2022-03-23T01:44:09.409Z drachtio:agent wp#send 0.0.0.0:9022 - 1259#72d53cec-92d9-4524-8f14-0df5cc9c7a69|sip||
INVITE sip:[email protected]:5038 SIP/2.0
User-Agent: drachtio-fsmrf:2931d499-e626-42e9-bd47-25717434a0a8
X-esl-outbound: 104.131.19.169:8099
Content-Length: 1040
v=0
o=- 4788793608 61235 IN IP4 104.131.19.169
s=qvfyufl
c=IN IP4 104.131.19.169
t=0 0
m=audio 20286 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20287
a=ptime:20
m=audio 20330 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20331
a=ptime:20
m=video 20360 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20361
m=video 20392 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20393
2022-03-23T01:44:09.415Z drachtio:agent <===1720#8d20c140-5113-47d1-9f5c-526426ae3e47|response|72d53cec-92d9-4524-8f14-0df5cc9c7a69|OK|application|1528|tcp|104.131.19.169|5038|01:44:09.414715|16b4bc2f-156f-4127-b4e1-744cece5e1e2|Msg sent:|
INVITE sip:[email protected]:5038 SIP/2.0
Via: SIP/2.0/UDP 104.131.19.169;rport;branch=z9hG4bKam6eS7Z37tDFB
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=vjygN8j0g4QUD
To: <sip:[email protected]:5038>
Call-ID: 9303db4e-24ed-123b-a191-0242ac110002
CSeq: 49446132 INVITE
Contact: <sip:104.131.19.169:5060>
User-Agent: drachtio-fsmrf:2931d499-e626-42e9-bd47-25717434a0a8
Content-Type: application/sdp
Content-Length: 1040
X-esl-outbound: 104.131.19.169:8099
v=0
o=- 4788793608 61235 IN IP4 104.131.19.169
s=qvfyufl
c=IN IP4 104.131.19.169
t=0 0
m=audio 20286 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20287
a=ptime:20
m=audio 20330 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20331
a=ptime:20
m=video 20360 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20361
m=video 20392 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20393
2022-03-23T01:44:41.419Z drachtio:agent <===467#e92d7b59-13fe-466b-b672-b58b3e5ea20b|sip|network|0|tcp||0|01:44:41.418704|16b4bc2f-156f-4127-b4e1-744cece5e1e2|9303db4e-24ed-123b-a191-0242ac110002;from-tag=vjygN8j0g4QUD|
SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 104.131.19.169;rport;branch=z9hG4bKam6eS7Z37tDFB
From: <sip:104.131.19.169:5060>;tag=vjygN8j0g4QUD
To: sip:[email protected]:5038;tag=XUQ9p333DDeeS
Call-ID: 9303db4e-24ed-123b-a191-0242ac110002
CSeq: 49446132 INVITE
Content-Length: 0
2022-03-23T01:44:41.419Z drachtio:agent tokens: ["e92d7b59-13fe-466b-b672-b58b3e5ea20b","sip","network","0","tcp","","0","01:44:41.418704","16b4bc2f-156f-4127-b4e1-744cece5e1e2","9303db4e-24ed-123b-a191-0242ac110002;from-tag=vjygN8j0g4QUD",""]
2022-03-23T01:44:41.419Z drachtio:agent received sip response
2022-03-23T01:44:41.419Z drachtio:agent Agent#handle: got a response with status: 408
2022-03-23T01:44:41.420Z drachtio:agent sendMessage: ACK sip:[email protected]:5038 SIP/2.0
Content-Length: 0
2022-03-23T01:44:41.420Z drachtio:agent opts: {"stackDialogId":"9303db4e-24ed-123b-a191-0242ac110002;from-tag=vjygN8j0g4QUD"}
2022-03-23T01:44:41.420Z drachtio:agent wp#send 0.0.0.0:9022 - 170#cbdde73b-7a9b-40f7-be5d-3971108f81be|sip||9303db4e-24ed-123b-a191-0242ac110002;from-tag=vjygN8j0g4QUD
ACK sip:[email protected]:5038 SIP/2.0
Content-Length: 0
{"level":30, "time": "2022-03-23T01:44:41.420Z","pid":1316316,"hostname":"east1","callId":"325713D374CE80D5756D68FB989AD5DB6A2A3DDC","msg":"Error: SipError: Sip non-success response: 408"}
{"level":30, "time": "2022-03-23T01:44:41.420Z","pid":1316316,"hostname":"east1","callId":"325713D374CE80D5756D68FB989AD5DB6A2A3DDC","stack":"Error: SipError: Sip non-success response: 408\n at CallSession.connect (/opt/vida.live/lib/call-session.js:87:17)\n at process._tickCallback (internal/process/next_tick.js:68:7)","type":"Error","msg":"unexpected error routing call"}
hanging up
2022-03-23T01:44:41.420Z drachtio:agent agent#sendResponse: {"headers":{"call-id":"325713D374CE80D5756D68FB989AD5DB6A2A3DDC","cseq":"2 INVITE","from":"<sip:[email protected]:5061>;tag=BFEDA5B4561099C4529C330F3986D56B","to":"<sip:[email protected]:5061>"},"status":603,"reason":"Decline"}
2022-03-23T01:44:41.420Z drachtio:agent sendMessage: SIP/2.0 603 Decline
Call-ID: 325713D374CE80D5756D68FB989AD5DB6A2A3DDC
cseq: 2 INVITE
from: <sip:[email protected]:5061>;tag=BFEDA5B4561099C4529C330F3986D56B
to: <sip:[email protected]:5061>
Content-Length: 0
2022-03-23T01:44:41.420Z drachtio:agent opts: {"stackTxnId":"6ff5aa93-5f60-4f4c-9b27-7120a1cd2d64"}
2022-03-23T01:44:41.420Z drachtio:agent Agent#sendResponse: deleted pending invite for call-id 325713D374CE80D5756D68FB989AD5DB6A2A3DDC, there are now 0 pending invites
{"level":30, "time": "2022-03-23T01:44:41.421Z","pid":1316316,"hostname":"east1","msg":"Call Session complete. undefined"}
2022-03-23T01:44:41.421Z drachtio:agent wp#send 0.0.0.0:9022 - 300#6627e234-1719-4736-9c2e-b867c1abba93|sip|6ff5aa93-5f60-4f4c-9b27-7120a1cd2d64|
SIP/2.0 603 Decline
Call-ID: 325713D374CE80D5756D68FB989AD5DB6A2A3DDC
cseq: 2 INVITE
from: <sip:[email protected]:5061>;tag=BFEDA5B4561099C4529C330F3986D56B
to: <sip:[email protected]:5061>
Content-Length: 0
2022-03-23T01:44:41.421Z drachtio:agent <===172#437cb5ef-33eb-4c0e-b18f-17a9b7fa305e|response|cbdde73b-7a9b-40f7-be5d-3971108f81be|NOK|Server error: ACK for non-success final response is automatically generated by server
2022-03-23T01:44:41.424Z drachtio:agent <===615#acb53e30-8613-469d-8b4c-9e7e2be719cc|response|6627e234-1719-4736-9c2e-b867c1abba93|OK|application|341|tcp|99.47.182.46|63023|01:44:41.423933|6ff5aa93-5f60-4f4c-9b27-7120a1cd2d64|325713D374CE80D5756D68FB989AD5DB6A2A3DDC;from-tag=BFEDA5B4561099C4529C330F3986D56B||Msg sent:|
SIP/2.0 603 Decline
Via: SIP/2.0/TLS 192.168.86.42:63023;branch=z9hG4bK4WdUrZPjKMYiNSRF;rport=63023;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=BFEDA5B4561099C4529C330F3986D56B
To: <sip:[email protected]:5061>;tag=y4g2rym7ap40m
Call-ID: 325713D374CE80D5756D68FB989AD5DB6A2A3DDC
CSeq: 2 INVITE
Content-Length: 0
** WORKING (v0.8.8) **
response from rtpengine to offer {"sdp":"v=0\r\no=- 6860282036 5798 IN IP4 104.131.19.169\r\ns=waugmsz\r\nc=IN IP4 104.131.19.169\r\nt=0 0\r\nm=audio 20116 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20117\r\na=ptime:20\r\nm=audio 20154 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20155\r\na=ptime:20\r\nm=video 20190 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20191\r\nm=video 20078 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20079\r\n","result":"ok"}
{"level":30, "time": "2022-03-23T01:49:43.742Z","pid":1316316,"hostname":"east1","callId":"232A1AC2D7C077339788C9E842133348B607ED67","msg":"Creating FreeSWITCH Broadcast endpoint."}
2022-03-23T01:49:43.742Z drachtio:agent options: {"uri":"sip:[email protected]:5038","method":"INVITE","headers":{"User-Agent":"drachtio-fsmrf:c191c2f3-8076-4571-b2ca-0887b6ed85f9","X-esl-outbound":"104.131.19.169:8099"},"body":"v=0\r\no=- 6860282036 5798 IN IP4 104.131.19.169\r\ns=waugmsz\r\nc=IN IP4 104.131.19.169\r\nt=0 0\r\nm=audio 20116 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20117\r\na=ptime:20\r\nm=audio 20154 RTP/AVP 103 0 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp:20155\r\na=ptime:20\r\nm=video 20190 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20191\r\nm=video 20078 RTP/AVP 99 108\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=rtpmap:108 VP8/90000\r\na=fmtp:108 max-fr=30;max-fs=3600\r\na=sendrecv\r\na=rtcp:20079\r\n"}
2022-03-23T01:49:43.743Z drachtio:agent wp#send 0.0.0.0:9022 - 1258#628d36b3-e18d-408b-9142-8634e563ea8b|sip||
INVITE sip:[email protected]:5038 SIP/2.0
User-Agent: drachtio-fsmrf:c191c2f3-8076-4571-b2ca-0887b6ed85f9
X-esl-outbound: 104.131.19.169:8099
Content-Length: 1039
v=0
o=- 6860282036 5798 IN IP4 104.131.19.169
s=waugmsz
c=IN IP4 104.131.19.169
t=0 0
m=audio 20116 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20117
a=ptime:20
m=audio 20154 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20155
a=ptime:20
m=video 20190 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20191
m=video 20078 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20079
2022-03-23T01:49:43.749Z drachtio:agent <===1719#df96ea14-0f88-4290-b381-229cf68d440b|response|628d36b3-e18d-408b-9142-8634e563ea8b|OK|application|1527|tcp|104.131.19.169|5038|01:49:43.748998|d744f62c-0323-41b2-8eca-0f07c1dac9ad|Msg sent:|
INVITE sip:[email protected]:5038 SIP/2.0
Via: SIP/2.0/TCP 104.131.19.169;rport;branch=z9hG4bKat3BQgc9gy2Sg
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=t6yrXXeB9SNtc
To: <sip:[email protected]:5038>
Call-ID: 5a4b3eb9-24ee-123b-8abf-0242ac110002
CSeq: 49446299 INVITE
Contact: <sip:104.131.19.169:5060>
User-Agent: drachtio-fsmrf:c191c2f3-8076-4571-b2ca-0887b6ed85f9
Content-Type: application/sdp
Content-Length: 1039
X-esl-outbound: 104.131.19.169:8099
v=0
o=- 6860282036 5798 IN IP4 104.131.19.169
s=waugmsz
c=IN IP4 104.131.19.169
t=0 0
m=audio 20116 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20117
a=ptime:20
m=audio 20154 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20155
a=ptime:20
m=video 20190 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20191
m=video 20078 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20079
2022-03-23T01:49:43.757Z drachtio:agent <===1449#7cf36cf5-5212-45a7-9e74-16e0243e57de|sip|network|1256|tcp|104.131.19.169|5038|01:49:43.757161|d744f62c-0323-41b2-8eca-0f07c1dac9ad|5a4b3eb9-24ee-123b-8abf-0242ac110002;from-tag=t6yrXXeB9SNtc|
SIP/2.0 200 OK
Via: SIP/2.0/TCP 104.131.19.169;rport=44127;branch=z9hG4bKat3BQgc9gy2Sg;received=172.17.0.2
From: <sip:104.131.19.169:5060>;tag=t6yrXXeB9SNtc
To: <sip:[email protected]:5038>;tag=yBvBXt7N9my0e
Call-ID: 5a4b3eb9-24ee-123b-8abf-0242ac110002
CSeq: 49446299 INVITE
Contact: <sip:[email protected]:5038;transport=udp>
User-Agent: drachtio mrf
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 517
Remote-Party-ID: "drachtio" <sip:[email protected]>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1647966195 1647966196 IN IP4 104.131.19.169
s=FreeSWITCH
c=IN IP4 104.131.19.169
t=0 0
m=audio 33988 RTP/AVP 103 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=rtcp:33989 IN IP4 104.131.19.169
m=audio 0 RTP/AVP 19
m=video 28150 RTP/AVP 99
b=AS:6144
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtcp:28151 IN IP4 104.131.19.169
m=video 0 RTP/AVP 19
2022-03-23T01:49:43.758Z drachtio:agent tokens: ["7cf36cf5-5212-45a7-9e74-16e0243e57de","sip","network","1256","tcp","104.131.19.169","5038","01:49:43.757161","d744f62c-0323-41b2-8eca-0f07c1dac9ad","5a4b3eb9-24ee-123b-8abf-0242ac110002;from-tag=t6yrXXeB9SNtc",""]
2022-03-23T01:49:43.758Z drachtio:agent received sip response
2022-03-23T01:49:43.758Z drachtio:agent Agent#handle: got a response with status: 200
2022-03-23T01:49:43.758Z drachtio:agent sendMessage: ACK sip:[email protected]:5038 SIP/2.0
Content-Length: 0
2022-03-23T01:49:43.758Z drachtio:agent opts: {"stackDialogId":"5a4b3eb9-24ee-123b-8abf-0242ac110002;from-tag=t6yrXXeB9SNtc"}
2022-03-23T01:49:43.759Z drachtio:agent wp#send 0.0.0.0:9022 - 170#8d964531-a21d-419d-a888-bf5ec3a0df3f|sip||5a4b3eb9-24ee-123b-8abf-0242ac110002;from-tag=t6yrXXeB9SNtc
ACK sip:[email protected]:5038 SIP/2.0
Content-Length: 0
2022-03-23T01:49:43.762Z drachtio:agent <===527#2f1086cd-11ff-4231-a729-0d1022b7539c|response|8d964531-a21d-419d-a888-bf5ec3a0df3f|OK|application|336|tcp|104.131.19.169|5038|01:49:43.760174|ff79d280-9f28-4fd6-8f76-021551926d8f|Msg sent:|
ACK sip:[email protected]:5038;transport=udp SIP/2.0
Via: SIP/2.0/TCP 104.131.19.169;branch=z9hG4bKB3v4rBXce7rcc
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=t6yrXXeB9SNtc
To: <sip:[email protected]:5038>;tag=yBvBXt7N9my0e
Call-ID: 5a4b3eb9-24ee-123b-8abf-0242ac110002
CSeq: 49446299 ACK
Content-Length: 0
2022-03-23T01:49:43.764Z drachtio:agent agent#sendResponse: {"headers":{"call-id":"232A1AC2D7C077339788C9E842133348B607ED67","cseq":"2 INVITE","from":"<sip:[email protected]:5061>;tag=51C1BDF830C57F3E52F1B5DEEA08138E","to":"<sip:[email protected]:5061>"},"status":200,"reason":"OK"}
2022-03-23T01:49:43.764Z drachtio:agent sendMessage: SIP/2.0 200 OK
Call-ID: 232A1AC2D7C077339788C9E842133348B607ED67
cseq: 2 INVITE
from: <sip:[email protected]:5061>;tag=51C1BDF830C57F3E52F1B5DEEA08138E
to: <sip:[email protected]:5061>
Content-Length: 0
2022-03-23T01:49:43.764Z drachtio:agent opts: {"stackTxnId":"5a83c728-d335-4a80-91a7-e6508187c01b","headers":{},"body":"v=0\r\no=FreeSWITCH 1647966195 1647966196 IN IP4 104.131.19.169\r\ns=FreeSWITCH\r\nc=IN IP4 104.131.19.169\r\nt=0 0\r\nm=audio 20136 RTP/SAVP 103 101\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 useinbandfec=1\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\na=sendrecv\r\na=rtcp:20137\r\na=setup:passive\r\na=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7\r\na=ptime:20\r\nm=audio 0 RTP/SAVP 19\r\nm=video 20066 RTP/SAVP 99\r\nb=AS:6144\r\na=rtpmap:99 H264/90000\r\na=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1\r\na=sendrecv\r\na=rtcp:20067\r\na=setup:passive\r\na=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7\r\nm=video 0 RTP/SAVP 19\r\n"}
2022-03-23T01:49:43.764Z drachtio:agent Agent#sendResponse: deleted pending invite for call-id 232A1AC2D7C077339788C9E842133348B607ED67, there are now 0 pending invites
2022-03-23T01:49:43.764Z drachtio:agent wp#send 0.0.0.0:9022 - 1070#e7cd59c8-411c-441d-9e37-13f4f91871e5|sip|5a83c728-d335-4a80-91a7-e6508187c01b|
SIP/2.0 200 OK
Call-ID: 232A1AC2D7C077339788C9E842133348B607ED67
cseq: 2 INVITE
from: <sip:[email protected]:5061>;tag=51C1BDF830C57F3E52F1B5DEEA08138E
to: <sip:[email protected]:5061>
Content-Length: 773
v=0
o=FreeSWITCH 1647966195 1647966196 IN IP4 104.131.19.169
s=FreeSWITCH
c=IN IP4 104.131.19.169
t=0 0
m=audio 20136 RTP/SAVP 103 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
a=rtcp:20137
a=setup:passive
a=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7
a=ptime:20
m=audio 0 RTP/SAVP 19
m=video 20066 RTP/SAVP 99
b=AS:6144
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
a=rtcp:20067
a=setup:passive
a=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7
m=video 0 RTP/SAVP 19
2022-03-23T01:49:43.767Z drachtio:agent <===1468#362818f2-39ad-48e0-83bd-a8700e181184|response|e7cd59c8-411c-441d-9e37-13f4f91871e5|OK|application|1193|tcp|99.47.182.46|63051|01:49:43.766668|5a83c728-d335-4a80-91a7-e6508187c01b|232A1AC2D7C077339788C9E842133348B607ED67;from-tag=51C1BDF830C57F3E52F1B5DEEA08138E||Msg sent:|
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.86.42:63051;branch=z9hG4bK37s6sQlZeAA299XB;rport=63051;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=51C1BDF830C57F3E52F1B5DEEA08138E
To: <sip:[email protected]:5061>;tag=UFrHZrZe62BDr
Call-ID: 232A1AC2D7C077339788C9E842133348B607ED67
CSeq: 2 INVITE
Contact: <sips:104.131.19.169:5061;transport=tls>
Content-Type: application/sdp
Content-Length: 773
v=0
o=FreeSWITCH 1647966195 1647966196 IN IP4 104.131.19.169
s=FreeSWITCH
c=IN IP4 104.131.19.169
t=0 0
m=audio 20136 RTP/SAVP 103 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
a=rtcp:20137
a=setup:passive
a=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7
a=ptime:20
m=audio 0 RTP/SAVP 19
m=video 20066 RTP/SAVP 99
b=AS:6144
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
a=rtcp:20067
a=setup:passive
a=fingerprint:sha-256 22:B3:B2:1C:6B:A3:45:43:22:BA:5B:50:A1:D6:13:3E:22:72:4D:E5:E0:2A:C3:2F:92:21:22:A8:E3:14:AA:D7
m=video 0 RTP/SAVP 19
Sure, here are the non-working drachtio-server logs (v0.8.11)
2022-03-23 02:04:50.435078 DrachtioController::processWatchdogTimer
2022-03-23 02:04:50.435233 size of hash table for server-side transactions 31
2022-03-23 02:04:50.435263 size of hash table for client-side transactions 31
2022-03-23 02:04:50.435282 size of hash table for dialogs 31
2022-03-23 02:04:50.435323 number of server-side transactions in the hash table 0
2022-03-23 02:04:50.435343 number of client-side transactions in the hash table 0
2022-03-23 02:04:50.435367 number of dialogs in the hash table 0
2022-03-23 02:04:50.435469 number of sip messages received 41
2022-03-23 02:04:50.435492 number of sip messages sent 42
2022-03-23 02:04:50.435514 number of sip requests received 39
2022-03-23 02:04:50.435534 number of sip requests sent 3
2022-03-23 02:04:50.435556 number of bad sip messages received 0
2022-03-23 02:04:50.435590 number of bad sip requests received 0
2022-03-23 02:04:50.435618 number of bad sip requests dropped 0
2022-03-23 02:04:50.435642 number of bad sip reponses dropped 0
2022-03-23 02:04:50.435734 number of client transactions created 3
2022-03-23 02:04:50.435765 number of server transactions created 15
2022-03-23 02:04:50.435811 number of in-dialog server transactions created 7
2022-03-23 02:04:50.435863 number of server transactions that have received ack 3
2022-03-23 02:04:50.435888 number of server transactions that have received cancel 0
2022-03-23 02:04:50.435938 number of requests that were processed stateless 29
2022-03-23 02:04:50.435983 number of requests converted to transactions by message callback 0
2022-03-23 02:04:50.436006 number of responses without matching request 0
2022-03-23 02:04:50.436044 number of successful responses missing INVITE client transaction 0
2022-03-23 02:04:50.436125 number of requests merged by UAS 0
2022-03-23 02:04:50.436147 number of SIP responses sent by stack 39
2022-03-23 02:04:50.436195 number of SIP requests retransmitted by stack 0
2022-03-23 02:04:50.436216 number of SIP responses retransmitted by stack 0
2022-03-23 02:04:50.436239 number of retransmitted SIP requests received by stack 0
2022-03-23 02:04:50.436273 number of SIP client transactions that has timeout 1
2022-03-23 02:04:50.436312 number of SIP server transactions that has timeout 0
2022-03-23 02:04:50.436352 SipDialogController storage counts
2022-03-23 02:04:50.436438 ----------------------------------
2022-03-23 02:04:50.436471 IIP size: 0
2022-03-23 02:04:50.436517 StableDialogs total size: 0
2022-03-23 02:04:50.436556 StableDialogs uac: 0
2022-03-23 02:04:50.436627 StableDialogs uas: 0
2022-03-23 02:04:50.436692 m_mapTransactionId2Irq size: 0
2022-03-23 02:04:50.436761 number of outgoing transactions held for timerD: 0
2022-03-23 02:04:50.436822 number of outgoing transactions waiting for ACK from app: 0
2022-03-23 02:04:50.436848 general queue size: 0
2022-03-23 02:04:50.436899 timer A queue size: 0
2022-03-23 02:04:50.436928 timer B queue size: 0
2022-03-23 02:04:50.436979 timer C queue size: 0
2022-03-23 02:04:50.437025 timer D queue size: 0
2022-03-23 02:04:50.437050 timer E queue size: 0
2022-03-23 02:04:50.437098 timer F queue size: 0
2022-03-23 02:04:50.437121 timer G queue size: 0
2022-03-23 02:04:50.437141 timer K queue size: 0
2022-03-23 02:04:50.437220 ClientController storage counts
2022-03-23 02:04:50.437288 ----------------------------------
2022-03-23 02:04:50.437360 m_clients size: 1
2022-03-23 02:04:50.437445 m_services size: 0
2022-03-23 02:04:50.437468 m_request_types size: 2
2022-03-23 02:04:50.437518 m_map_of_request_type_offsets size: 2
2022-03-23 02:04:50.437566 m_mapDialogs size: 0
2022-03-23 02:04:50.437616 m_mapNetTransactions size: 0
2022-03-23 02:04:50.437662 m_mapAppTransactions size: 0
2022-03-23 02:04:50.437730 m_mapApiRequests size: 0
2022-03-23 02:04:50.437780 m_mapDialogId2Appname size: 0
2022-03-23 02:04:50.437831 PendingRequestController storage counts
2022-03-23 02:04:50.437853 ----------------------------------
2022-03-23 02:04:50.437900 m_mapCallId2Invite size: 0
2022-03-23 02:04:50.437923 m_mapTxnId2Invite size: 0
2022-03-23 02:04:50.437942 SipProxyController storage counts
2022-03-23 02:04:50.437991 ----------------------------------
2022-03-23 02:04:50.438057 m_mapCallId2Proxy size: 0
2022-03-23 02:04:50.438078 m_mapNonce2Challenge size: 0
2022-03-23 02:04:50.438147 general queue size: 0
2022-03-23 02:04:50.438219 timer A queue size: 0
2022-03-23 02:04:50.438288 timer B queue size: 0
2022-03-23 02:04:50.438354 timer C queue size: 0
2022-03-23 02:04:50.438422 timer D queue size: 0
2022-03-23 02:04:50.438502 timer E queue size: 0
2022-03-23 02:04:50.438589 timer F queue size: 0
2022-03-23 02:04:50.438611 timer G queue size: 0
2022-03-23 02:04:50.438670 timer K queue size: 0
2022-03-23 02:04:50.438748 m_mapUri2InvalidData size: 1
2022-03-23 02:04:52.550481 tport.c:2801 tport_wakeup() tport_wakeup(0x55e385513e90): events IN
2022-03-23 02:04:52.550641 tport.c:2892 tport_recv_event() tport_recv_event(0x55e385513e90)
2022-03-23 02:04:52.550682 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e385513e90): tls_read() returned 1756
2022-03-23 02:04:52.550719 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e385513e90) msg 0x55e38552f5d0 from (tls/99.47.182.46:63097) has 1756 bytes, veclen = 1
2022-03-23 02:04:52.551135 recv 1756 bytes from tls/[99.47.182.46]:63097 at 02:04:52.550814:
INVITE sip:[email protected]:5061 SIP/2.0
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKQmsXrszyc0AM71IZ;rport
Contact: <sip:[email protected]:63097;transport=tls>
Max-Forwards: 70
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
To: <sip:[email protected]:5061>
Content-Type: application/sdp
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 1 INVITE
User-Agent: VIDA/0.0.6
Content-Length: 1212
v=0
o=- 5994113522 48578 IN IP4 172.26.170.170
s=mqzkcra
c=IN IP4 99.47.182.46
t=0 0
m=audio 47258 RTP/SAVP 103 0 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
a=setup:actpass
a=fingerprint:sha-256 E1:1F:F4:9A:EB:93:DB:A1:C2:AA:C1:69:51:29:2F:29:2B:8B:B6:A1:14:2A:B0:B7:88:90:01:7D:2B:20:4A:85
m=audio 47258 RTP/AVP 103 0 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
m=video 29196 RTP/SAVP 99 108
a=rtpmap:108 VP8/90000
a=rtpmap:99 H264/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
a=setup:actpass
a=fingerprint:sha-256 E1:1F:F4:9A:EB:93:DB:A1:C2:AA:C1:69:51:29:2F:29:2B:8B:B6:A1:14:2A:B0:B7:88:90:01:7D:2B:20:4A:85
m=video 29196 RTP/AVP 99 108
a=rtpmap:108 VP8/90000
a=rtpmap:99 H264/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
2022-03-23 02:04:52.551176 tport.c:3051 tport_deliver() tport_deliver(0x55e385513e90): msg 0x55e38552f5d0 (1756 bytes) from tls/99.47.182.46:63097 next=(nil)
2022-03-23 02:04:52.551409 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.551467 nta.c:3039 agent_recv_request() nta: received INVITE sip:[email protected]:5061 SIP/2.0 (CSeq 1)
2022-03-23 02:04:52.551516 nta.c:3334 agent_check_request_via() nta: Via check: received=99.47.182.46
2022-03-23 02:04:52.551602 nta.c:3254 agent_recv_request() nta: INVITE (1) to message callback
2022-03-23 02:04:52.551634 processMessageStatelessly - incoming message with call-id 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C does not match an existing call leg, processed in thread 140074811344192
2022-03-23 02:04:52.551688 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.551728 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.551788 processMessageStatelessly- called nta_incoming_transport
2022-03-23 02:04:52.551898 tport.c:3285 tport_tsend() tport_tsend(0x55e385513e90) tpn = TLS/99.47.182.46:63097
2022-03-23 02:04:52.552046 tport_type_tls.c:594 tport_tls_send() tport_tls_writevec: vec 0x55e385523530 0x55e385516260 322 (322)
2022-03-23 02:04:52.552092 tport.c:3534 tport_send_msg() tport_vsend returned 322
2022-03-23 02:04:52.552261 send 322 bytes to tls/[99.47.182.46]:63097 at 02:04:52.551969:
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKQmsXrszyc0AM71IZ;rport=63097;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 1 INVITE
Content-Length: 0
2022-03-23 02:04:52.552305 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.552373 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0
2022-03-23 02:04:52.552409 ClientController::route_request_outside_dialog - Selected client at offset 0
2022-03-23 02:04:52.552447 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.552493 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.552594 PendingRequestController::add - tport: 0x55e385513e90, Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C, transactionId 4716f2a8-9d5c-4ad1-a634-47c9038be314
2022-03-23 02:04:52.552666 pending-request: Adding entry to go off in 64000ms
2022-03-23 02:04:52.552706 pending-request: Adding entry to the head (queue was empty), length: 1
2022-03-23 02:04:52.552827 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.552858 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.552914 ClientController::addNetTransaction: transactionId 4716f2a8-9d5c-4ad1-a634-47c9038be314; size: 1
2022-03-23 02:04:52.553033 No connected clients found to handle incoming cdr:attempt request
2022-03-23 02:04:52.553078 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 1
2022-03-23 02:04:52.553179 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.553270 Client::write_handler - wrote 1938 bytes: system:0
2022-03-23 02:04:52.594476 Client::read_handler read: 1d94c688-3839-4093-83cd-734794e83451|sip|4716f2a8-9d5c-4ad1-a634-47c9038be314|
SIP/2.0 401 Unauthorized
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
cseq: 1 INVITE
from: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
to: <sip:[email protected]:5061>
Content-Length: 0
www-authenticate: Digest realm="vida.live", algorithm=MD5, qop="auth", nonce="164800109259300"
2022-03-23 02:04:52.594791 Client::processMessage - got request with 4 tokens
2022-03-23 02:04:52.594915 Client::processMessage - request id 1d94c688-3839-4093-83cd-734794e83451, request type: sip transaction id: 4716f2a8-9d5c-4ad1-a634-47c9038be314, dialog id:
2022-03-23 02:04:52.595078 ClientController::addApiRequest: clientMsgId 1d94c688-3839-4093-83cd-734794e83451; size: 1
2022-03-23 02:04:52.595222 SipDialogController::doRespondToSipRequest thread 140074811344192
2022-03-23 02:04:52.595288 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 4716f2a8-9d5c-4ad1-a634-47c9038be314
2022-03-23 02:04:52.595393 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId 4716f2a8-9d5c-4ad1-a634-47c9038be314, most likely this is a response to an invite we sent
2022-03-23 02:04:52.595576 pending-request: removing entry, prior to removal length: 1
2022-03-23 02:04:52.595612 pending-request: removed entry, timer not set (queue is empty after removal), length: 0
2022-03-23 02:04:52.595683 nta.c:1411 set_timeout() nta: timer set to 2000 ms
2022-03-23 02:04:52.595717 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.595798 nta.c:4577 nta_leg_tcreate() nta_leg_tcreate(0x55e38554e290)
2022-03-23 02:04:52.595827 DrachtioController::setupLegForIncomingRequest - created leg: 0x55e38554e290, irq: 0x55e385532b20, for transactionId: 4716f2a8-9d5c-4ad1-a634-47c9038be314, tag:
2022-03-23 02:04:52.595883 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.595935 SipDialog::SipDialog - creating dialog for inbound INVITE sent from TLS/99.47.182.46:63097
2022-03-23 02:04:52.595970 adding IIP for incoming call tid:4716f2a8-9d5c-4ad1-a634-47c9038be314 alive:0s leg:0x55e38554e290 irq:0x55e385532b20 orq:0 rel:0
2022-03-23 02:04:52.595995 IIP_Insert incoming - ref count: 1 inserting tid:4716f2a8-9d5c-4ad1-a634-47c9038be314 alive:0s leg:0x55e38554e290 irq:0x55e385532b20 orq:0 rel:0
2022-03-23 02:04:52.596036 SipDialogController::doRespondToSipRequest found invite or subscribe in progress 0x55e385529440
2022-03-23 02:04:52.596060 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:04:52.596085 SipTransport::getContactUri - created Contact header: sips:104.131.19.169:5061;transport=tls
2022-03-23 02:04:52.596109 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.596368 makeTags - Adding well-known header 'Call-ID' with value '566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C'
2022-03-23 02:04:52.596398 makeTags - Adding well-known header 'cseq' with value '1 INVITE'
2022-03-23 02:04:52.596423 makeTags - Adding well-known header 'from' with value '<sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91'
2022-03-23 02:04:52.596449 makeTags - Adding well-known header 'to' with value '<sip:[email protected]:5061>'
2022-03-23 02:04:52.596484 makeTags - Adding well-known header 'www-authenticate' with value 'Digest realm="vida.live", algorithm=MD5, qop="auth", nonce="164800109259300"'
2022-03-23 02:04:52.596509 Sending 401 response (not reliably) on irq 0x55e385532b20
2022-03-23 02:04:52.596553 tport.c:3285 tport_tsend() tport_tsend(0x55e385513e90) tpn = TLS/99.47.182.46:63097
2022-03-23 02:04:52.596665 tport_type_tls.c:594 tport_tls_send() tport_tls_writevec: vec 0x55e385523530 0x55e385516260 442 (442)
2022-03-23 02:04:52.596696 tport.c:3534 tport_send_msg() tport_vsend returned 442
2022-03-23 02:04:52.596918 send 442 bytes to tls/[99.47.182.46]:63097 at 02:04:52.596583:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKQmsXrszyc0AM71IZ;rport=63097;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>;tag=KU1Nay6510m8F
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 1 INVITE
WWW-Authenticate: Digest realm="vida.live", algorithm=MD5, qop="auth", nonce="164800109259300"
Content-Length: 0
2022-03-23 02:04:52.596966 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.597067 nta.c:6950 incoming_reply() nta: sent 401 Unauthorized for INVITE (1)
2022-03-23 02:04:52.597127 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:04:52.597183 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.597233 ClientController::removeApiRequest: clientMsgId 1d94c688-3839-4093-83cd-734794e83451; size: 0
2022-03-23 02:04:52.597283 No connected clients found to handle incoming cdr:stop request
2022-03-23 02:04:52.597310 ClientController::removeNetTransaction: transactionId 4716f2a8-9d5c-4ad1-a634-47c9038be314; size: 0
2022-03-23 02:04:52.597544 Client::write_handler - wrote 720 bytes: system:0
2022-03-23 02:04:52.645676 tport.c:2801 tport_wakeup() tport_wakeup(0x55e385513e90): events IN
2022-03-23 02:04:52.645858 tport.c:2892 tport_recv_event() tport_recv_event(0x55e385513e90)
2022-03-23 02:04:52.646068 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e385513e90): tls_read() returned 373
2022-03-23 02:04:52.646136 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e385513e90) msg 0x55e38553d2a0 from (tls/99.47.182.46:63097) has 373 bytes, veclen = 1
2022-03-23 02:04:52.646377 recv 373 bytes from tls/[99.47.182.46]:63097 at 02:04:52.646227:
ACK sip:[email protected]:5061 SIP/2.0
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKQmsXrszyc0AM71IZ;rport
Max-Forwards: 70
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>;tag=KU1Nay6510m8F
CSeq: 1 ACK
User-Agent: VIDA/0.0.6
Content-Length: 0
2022-03-23 02:04:52.646433 tport.c:3051 tport_deliver() tport_deliver(0x55e385513e90): msg 0x55e38553d2a0 (373 bytes) from tls/99.47.182.46:63097 next=(nil)
2022-03-23 02:04:52.646463 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:04:52.646495 nta.c:3039 agent_recv_request() nta: received ACK sip:[email protected]:5061 SIP/2.0 (CSeq 1)
2022-03-23 02:04:52.646559 nta.c:3334 agent_check_request_via() nta: Via check: received=99.47.182.46
2022-03-23 02:04:52.646617 nta.c:3178 agent_recv_request() nta: ACK (1) is going to INVITE (1)
2022-03-23 02:04:52.646730 SipDialogController::processCancelOrAck: ACK
2022-03-23 02:04:52.646906 SipDialogController::clearSipTimers for 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
2022-03-23 02:04:52.647008 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 5
2022-03-23 02:04:52.647066 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 4
2022-03-23 02:04:52.647196 ClientController::route_ack_request_inside_dialog - client managing dialog has disconnected, or the call was rejected as part of outbound request handler: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C;from-tag=53B086C53DC49F7A93A59F123EB1AE91
2022-03-23 02:04:52.647257 SipDialog::~SipDialog - destroying sip dialog with call-id 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
2022-03-23 02:04:52.647339 nta.c:4630 nta_leg_destroy() nta_leg_destroy(0x55e38554e290)
2022-03-23 02:04:52.647391 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.647447 nta.c:5903 incoming_free() nta: incoming_free(0x55e385532b20)
2022-03-23 02:04:52.647495 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.647562 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 1
2022-03-23 02:04:52.647616 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.647698 tport.c:2801 tport_wakeup() tport_wakeup(0x55e385513e90): events IN
2022-03-23 02:04:52.647851 tport.c:2892 tport_recv_event() tport_recv_event(0x55e385513e90)
2022-03-23 02:04:52.647895 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e385513e90): tls_read() returned 1990
2022-03-23 02:04:52.647969 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e385513e90) msg 0x55e385517bb0 from (tls/99.47.182.46:63097) has 1990 bytes, veclen = 1
2022-03-23 02:04:52.648396 recv 1990 bytes from tls/[99.47.182.46]:63097 at 02:04:52.648034:
INVITE sip:[email protected]:5061 SIP/2.0
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKdNOa427pBsQoGcYl;rport
Contact: <sip:[email protected]:63097;transport=tls>
Max-Forwards: 70
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
To: <sip:[email protected]:5061>
Content-Type: application/sdp
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 2 INVITE
Authorization: Digest username="lylepratt",realm="vida.live",algorithm=MD5,uri="sip:[email protected]:5061",nonce="164800109259300",qop=auth,cnonce="YjqARMacLI9HHSt9ooqJnSvs",nc=00000001,response="e7c5a5fe3c936c620fbc68c5dce8ddcc"
User-Agent: VIDA/0.0.6
Content-Length: 1212
v=0
o=- 5994113522 48578 IN IP4 172.26.170.170
s=mqzkcra
c=IN IP4 99.47.182.46
t=0 0
m=audio 47258 RTP/SAVP 103 0 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
a=setup:actpass
a=fingerprint:sha-256 E1:1F:F4:9A:EB:93:DB:A1:C2:AA:C1:69:51:29:2F:29:2B:8B:B6:A1:14:2A:B0:B7:88:90:01:7D:2B:20:4A:85
m=audio 47258 RTP/AVP 103 0 101
a=rtpmap:101 telephone-event/8000
a=rtpmap:103 opus/48000/2
a=fmtp:101 0-15
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=ptime:20
a=sendrecv
m=video 29196 RTP/SAVP 99 108
a=rtpmap:108 VP8/90000
a=rtpmap:99 H264/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
a=setup:actpass
a=fingerprint:sha-256 E1:1F:F4:9A:EB:93:DB:A1:C2:AA:C1:69:51:29:2F:29:2B:8B:B6:A1:14:2A:B0:B7:88:90:01:7D:2B:20:4A:85
m=video 29196 RTP/AVP 99 108
a=rtpmap:108 VP8/90000
a=rtpmap:99 H264/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=sendrecv
2022-03-23 02:04:52.648441 tport.c:3051 tport_deliver() tport_deliver(0x55e385513e90): msg 0x55e385517bb0 (1990 bytes) from tls/99.47.182.46:63097 next=(nil)
2022-03-23 02:04:52.648470 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.648514 nta.c:3039 agent_recv_request() nta: received INVITE sip:[email protected]:5061 SIP/2.0 (CSeq 2)
2022-03-23 02:04:52.648566 nta.c:3334 agent_check_request_via() nta: Via check: received=99.47.182.46
2022-03-23 02:04:52.648608 nta.c:3254 agent_recv_request() nta: INVITE (2) to message callback
2022-03-23 02:04:52.648658 processMessageStatelessly - incoming message with call-id 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C does not match an existing call leg, processed in thread 140074811344192
2022-03-23 02:04:52.648693 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.648719 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.648834 processMessageStatelessly- called nta_incoming_transport
2022-03-23 02:04:52.648941 tport.c:3285 tport_tsend() tport_tsend(0x55e385513e90) tpn = TLS/99.47.182.46:63097
2022-03-23 02:04:52.649088 tport_type_tls.c:594 tport_tls_send() tport_tls_writevec: vec 0x55e385523530 0x55e385516260 322 (322)
2022-03-23 02:04:52.649133 tport.c:3534 tport_send_msg() tport_vsend returned 322
2022-03-23 02:04:52.649311 send 322 bytes to tls/[99.47.182.46]:63097 at 02:04:52.648985:
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKdNOa427pBsQoGcYl;rport=63097;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 2 INVITE
Content-Length: 0
2022-03-23 02:04:52.649353 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.649438 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0
2022-03-23 02:04:52.649496 ClientController::route_request_outside_dialog - Selected client at offset 0
2022-03-23 02:04:52.649552 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.649585 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.649657 PendingRequestController::add - tport: 0x55e385513e90, Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C, transactionId 8be42c7b-34cc-4265-9570-1837e0d4b451
2022-03-23 02:04:52.649730 pending-request: Adding entry to go off in 64000ms
2022-03-23 02:04:52.649764 pending-request: Adding entry to the head (queue was empty), length: 1
2022-03-23 02:04:52.649828 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:04:52.649883 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:04:52.649942 ClientController::addNetTransaction: transactionId 8be42c7b-34cc-4265-9570-1837e0d4b451; size: 1
2022-03-23 02:04:52.650036 No connected clients found to handle incoming cdr:attempt request
2022-03-23 02:04:52.650082 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 1
2022-03-23 02:04:52.650152 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:04:52.650367 Client::write_handler - wrote 2172 bytes: system:0
2022-03-23 02:04:52.742986 Client::read_handler read: 1b87e5a1-c593-4989-a600-651977389b63|sip||
INVITE sip:[email protected]:5038 SIP/2.0
User-Agent: drachtio-fsmrf:f1887cf8-992d-4a90-a0fc-2a41f34b0e79
X-esl-outbound: 104.131.19.169:8099
Content-Length: 1040
v=0
o=- 5994113522 48578 IN IP4 104.131.19.169
s=mqzkcra
c=IN IP4 104.131.19.169
t=0 0
m=audio 20218 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20219
a=ptime:20
m=audio 20256 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20257
a=ptime:20
m=video 20096 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20097
m=video 20120 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20121
2022-03-23 02:04:52.743099 Client::processMessage - got request with 4 tokens
2022-03-23 02:04:52.743129 Client::processMessage - request id 1b87e5a1-c593-4989-a600-651977389b63, request type: sip transaction id: , dialog id:
2022-03-23 02:04:52.743176 Client::processMessage - sending a request outside of a dialog
2022-03-23 02:04:52.743223 ClientController::addAppTransaction: transactionId 4cb71bdf-fdcc-416e-bb81-91fa669ad0a3; size: 1
2022-03-23 02:04:52.743250 ClientController::addApiRequest: clientMsgId 1b87e5a1-c593-4989-a600-651977389b63; size: 1
2022-03-23 02:04:52.743459 DrachtioController::findTportForSubscription: no transport found for [email protected]
2022-03-23 02:04:52.745088 SipTransport::findAppropriateTransport: searching for a transport to reach udp/sip:[email protected]:5038
2022-03-23 02:04:52.745161 SipTransport::findAppropriateTransport - after filtering for transport we have 10 candidates
2022-03-23 02:04:52.745191 SipTransport::findAppropriateTransport - after filtering for protocol we have 2 candidates
2022-03-23 02:04:52.746675 SipTransport::findAppropriateTransport: - returning the best match 0x55e3854e02c0: udp/127.0.0.1:5060
2022-03-23 02:04:52.746727 SipTransport::getContactUri - created Contact header: sip:104.131.19.169:5060
2022-03-23 02:04:52.746750 SipDialogController::doSendRequestOutsideDialog selected transport 0x55e3854e02c0udp/127.0.0.1:5060
2022-03-23 02:04:52.747036 makeTags - using external IP as replacement for 'localhost': 104.131.19.169
2022-03-23 02:04:52.747167 makeTags - Adding well-known header 'User-Agent' with value 'drachtio-fsmrf:f1887cf8-992d-4a90-a0fc-2a41f34b0e79'
2022-03-23 02:04:52.747279 makeTags - custom header: 'X-esl-outbound', value: 104.131.19.169:8099
2022-03-23 02:04:52.747407 SipDialogController::doSendRequestOutsideDialog - from: <sip:104.131.19.169:5060>
2022-03-23 02:04:52.747454 SipDialogController::doSendRequestOutsideDialog - to: sip:[email protected]:5038
2022-03-23 02:04:52.747534 SipDialogController::doSendRequestOutsideDialog - contact: <sip:104.131.19.169:5060>
2022-03-23 02:04:52.747651 SipDialogController::doSendRequestOutsideDialog - automatically detecting content-type as application/sdp
2022-03-23 02:04:52.747718 isLocalSipUri: checking to see if this is one of mine: sip:[email protected]:5038
2022-03-23 02:04:52.747836 nta.c:4577 nta_leg_tcreate() nta_leg_tcreate(0x55e385532e60)
2022-03-23 02:04:52.747974 nta.c:2824 nta_tpn_by_url() nta: selecting scheme sip
2022-03-23 02:04:52.748074 tport.c:1157 tport_ref() tport_ref(0x55e3854defc0): refcount is now 1
2022-03-23 02:04:52.748156 tport.c:3285 tport_tsend() tport_tsend(0x55e3854defc0) tpn = */104.131.19.169:5038
2022-03-23 02:04:52.748238 tport.c:4088 tport_resolve() tport_resolve addrinfo = 104.131.19.169:5038
2022-03-23 02:04:52.748271 tport.c:4774 tport_by_addrinfo() tport_by_addrinfo(0x55e3854defc0): not found by name */104.131.19.169:5038
2022-03-23 02:04:52.748363 tport.c:4770 tport_by_addrinfo() tport_by_addrinfo(0x55e3854df4a0): found 0x55e385530920 by name */104.131.19.169:5038
2022-03-23 02:04:52.748572 tport.c:3534 tport_send_msg() tport_vsend returned 1528
2022-03-23 02:04:52.748893 send 1528 bytes to tcp/[104.131.19.169]:5038 at 02:04:52.748509:
INVITE sip:[email protected]:5038 SIP/2.0
Via: SIP/2.0/UDP 104.131.19.169;rport;branch=z9hG4bKpD35Ftam6FcgQ
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=m4tecSQ9y9aUB
To: <sip:[email protected]:5038>
Call-ID: 781995d1-24f0-123b-50bd-0242ac110002
CSeq: 49446754 INVITE
Contact: <sip:104.131.19.169:5060>
User-Agent: drachtio-fsmrf:f1887cf8-992d-4a90-a0fc-2a41f34b0e79
Content-Type: application/sdp
Content-Length: 1040
X-esl-outbound: 104.131.19.169:8099
v=0
o=- 5994113522 48578 IN IP4 104.131.19.169
s=mqzkcra
c=IN IP4 104.131.19.169
t=0 0
m=audio 20218 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20219
a=ptime:20
m=audio 20256 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20257
a=ptime:20
m=video 20096 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20097
m=video 20120 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20121
2022-03-23 02:04:52.748945 tport.c:2324 tport_set_secondary_timer() tport(0x55e385530920): reset timer
2022-03-23 02:04:52.749178 nta.c:8481 outgoing_send() nta: sent INVITE (49446754) to */104.131.19.169:5038
2022-03-23 02:04:52.749257 tport.c:4202 tport_pend() tport_pend(0x55e385530920): pending 0x55e38552f5d0 for tcp/104.131.19.169:5038 (already 0)
2022-03-23 02:04:52.749324 tport.c:1170 tport_unref() tport_unref(0x55e3854defc0): refcount is now 0
2022-03-23 02:04:52.749398 tport.c:1157 tport_ref() tport_ref(0x55e385530920): refcount is now 3
2022-03-23 02:04:52.749473 SipDialogController::doSendRequestOutsideDialog - created orq 0x55e385533a20 call-id 781995d1-24f0-123b-50bd-0242ac110002 / transaction id: 4cb71bdf-fdcc-416e-bb81-91fa669ad0a3
2022-03-23 02:04:52.749598 tport.c:1157 tport_ref() tport_ref(0x55e385530920): refcount is now 4
2022-03-23 02:04:52.749701 SipDialog::SipDialog - creating dialog for outbound INVITE sent from tcp/104.131.19.169:5038 to 104.131.19.169:5038
2022-03-23 02:04:52.749740 SipDialogController::addOutgoingInviteTransaction: adding leg 0x55e385532e60
2022-03-23 02:04:52.749868 adding IIP for outgoing call tid:4cb71bdf-fdcc-416e-bb81-91fa669ad0a3 alive:0s leg:0x55e385532e60 irq:0 orq:0x55e385533a20 rel:0
2022-03-23 02:04:52.749907 IIP_Insert outgoing - ref count: 1 inserting tid:4cb71bdf-fdcc-416e-bb81-91fa669ad0a3 alive:0s leg:0x55e385532e60 irq:0 orq:0x55e385533a20 rel:0
2022-03-23 02:04:52.750063 No connected clients found to handle incoming cdr:attempt request
2022-03-23 02:04:52.750151 tport.c:1157 tport_ref() tport_ref(0x55e385530920): refcount is now 5
2022-03-23 02:04:52.750196 tport.c:1170 tport_unref() tport_unref(0x55e385530920): refcount is now 4
2022-03-23 02:04:52.750324 ClientController::removeApiRequest: clientMsgId 1b87e5a1-c593-4989-a600-651977389b63; size: 0
2022-03-23 02:04:52.750639 Client::write_handler - wrote 1725 bytes: system:0
2022-03-23 02:04:54.598357 nta.c:1357 agent_timer() nta: timer set next to 30151 ms
2022-03-23 02:05:16.952161 tport.c:2801 tport_wakeup() tport_wakeup(0x55e3854de8b0): events IN
2022-03-23 02:05:16.952335 tport.c:2892 tport_recv_event() tport_recv_event(0x55e3854de8b0)
2022-03-23 02:05:16.952384 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e3854de8b0): tls_read() returned 4
2022-03-23 02:05:16.952423 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e3854de8b0) msg 0x55e385530f70 from (tls/99.47.182.46:63114) has 4 bytes, veclen = 1
2022-03-23 02:05:16.952459 tport.c:2324 tport_set_secondary_timer() tport(0x55e3854de8b0): reset timer
2022-03-23 02:05:19.952957 tport.c:2801 tport_wakeup() tport_wakeup(0x55e385513e90): events IN
2022-03-23 02:05:19.953104 tport.c:2892 tport_recv_event() tport_recv_event(0x55e385513e90)
2022-03-23 02:05:19.953129 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e385513e90): tls_read() returned 4
2022-03-23 02:05:19.953159 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e385513e90) msg 0x55e38553d2a0 from (tls/99.47.182.46:63097) has 4 bytes, veclen = 1
2022-03-23 02:05:19.953188 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:05:20.435760 DrachtioController::processWatchdogTimer
2022-03-23 02:05:20.435889 size of hash table for server-side transactions 31
2022-03-23 02:05:20.435914 size of hash table for client-side transactions 31
2022-03-23 02:05:20.435935 size of hash table for dialogs 31
2022-03-23 02:05:20.435954 number of server-side transactions in the hash table 0
2022-03-23 02:05:20.435995 number of client-side transactions in the hash table 1
2022-03-23 02:05:20.436014 number of dialogs in the hash table 1
2022-03-23 02:05:20.436036 number of sip messages received 44
2022-03-23 02:05:20.436084 number of sip messages sent 46
2022-03-23 02:05:20.436178 number of sip requests received 42
2022-03-23 02:05:20.436200 number of sip requests sent 4
2022-03-23 02:05:20.436277 number of bad sip messages received 0
2022-03-23 02:05:20.436327 number of bad sip requests received 0
2022-03-23 02:05:20.436407 number of bad sip requests dropped 0
2022-03-23 02:05:20.436484 number of bad sip reponses dropped 0
2022-03-23 02:05:20.436508 number of client transactions created 4
2022-03-23 02:05:20.436571 number of server transactions created 16
2022-03-23 02:05:20.436651 number of in-dialog server transactions created 7
2022-03-23 02:05:20.436726 number of server transactions that have received ack 4
2022-03-23 02:05:20.436794 number of server transactions that have received cancel 0
2022-03-23 02:05:20.436893 number of requests that were processed stateless 31
2022-03-23 02:05:20.436969 number of requests converted to transactions by message callback 0
2022-03-23 02:05:20.437033 number of responses without matching request 0
2022-03-23 02:05:20.437097 number of successful responses missing INVITE client transaction 0
2022-03-23 02:05:20.437119 number of requests merged by UAS 0
2022-03-23 02:05:20.437171 number of SIP responses sent by stack 42
2022-03-23 02:05:20.437254 number of SIP requests retransmitted by stack 0
2022-03-23 02:05:20.437297 number of SIP responses retransmitted by stack 0
2022-03-23 02:05:20.437386 number of retransmitted SIP requests received by stack 0
2022-03-23 02:05:20.437410 number of SIP client transactions that has timeout 1
2022-03-23 02:05:20.437430 number of SIP server transactions that has timeout 0
2022-03-23 02:05:20.437485 SipDialogController storage counts
2022-03-23 02:05:20.437507 ----------------------------------
2022-03-23 02:05:20.437591 IIP size: 1
2022-03-23 02:05:20.437625 StableDialogs total size: 0
2022-03-23 02:05:20.437671 StableDialogs uac: 0
2022-03-23 02:05:20.437762 StableDialogs uas: 0
2022-03-23 02:05:20.437825 m_mapTransactionId2Irq size: 0
2022-03-23 02:05:20.437849 number of outgoing transactions held for timerD: 0
2022-03-23 02:05:20.437871 number of outgoing transactions waiting for ACK from app: 0
2022-03-23 02:05:20.437894 general queue size: 0
2022-03-23 02:05:20.437916 timer A queue size: 0
2022-03-23 02:05:20.437938 timer B queue size: 0
2022-03-23 02:05:20.437957 timer C queue size: 0
2022-03-23 02:05:20.437975 timer D queue size: 0
2022-03-23 02:05:20.437994 timer E queue size: 0
2022-03-23 02:05:20.438015 timer F queue size: 0
2022-03-23 02:05:20.438036 timer G queue size: 0
2022-03-23 02:05:20.438054 timer K queue size: 0
2022-03-23 02:05:20.438076 ClientController storage counts
2022-03-23 02:05:20.438111 ----------------------------------
2022-03-23 02:05:20.438134 m_clients size: 1
2022-03-23 02:05:20.438155 m_services size: 0
2022-03-23 02:05:20.438175 m_request_types size: 2
2022-03-23 02:05:20.438194 m_map_of_request_type_offsets size: 2
2022-03-23 02:05:20.438215 m_mapDialogs size: 0
2022-03-23 02:05:20.438234 m_mapNetTransactions size: 1
2022-03-23 02:05:20.438254 m_mapAppTransactions size: 1
2022-03-23 02:05:20.438276 m_mapApiRequests size: 0
2022-03-23 02:05:20.438297 m_mapDialogId2Appname size: 0
2022-03-23 02:05:20.438319 PendingRequestController storage counts
2022-03-23 02:05:20.438340 ----------------------------------
2022-03-23 02:05:20.438358 m_mapCallId2Invite size: 1
2022-03-23 02:05:20.438470 m_mapTxnId2Invite size: 1
2022-03-23 02:05:20.438509 SipProxyController storage counts
2022-03-23 02:05:20.438556 ----------------------------------
2022-03-23 02:05:20.438584 m_mapCallId2Proxy size: 0
2022-03-23 02:05:20.438626 m_mapNonce2Challenge size: 0
2022-03-23 02:05:20.438663 general queue size: 0
2022-03-23 02:05:20.438691 timer A queue size: 0
2022-03-23 02:05:20.438710 timer B queue size: 0
2022-03-23 02:05:20.438731 timer C queue size: 0
2022-03-23 02:05:20.438753 timer D queue size: 0
2022-03-23 02:05:20.438771 timer E queue size: 0
2022-03-23 02:05:20.438793 timer F queue size: 0
2022-03-23 02:05:20.438812 timer G queue size: 0
2022-03-23 02:05:20.438831 timer K queue size: 0
2022-03-23 02:05:20.438849 m_mapUri2InvalidData size: 1
2022-03-23 02:05:24.756273 nta.c:9159 outgoing_timer_bf() nta: timer B fired, timeout INVITE (49446754)
2022-03-23 02:05:24.756387 tport.c:4264 tport_release() tport_release(0x55e385530920): 0x55e38552f5d0 by 0x55e385533a20 with (nil)
2022-03-23 02:05:24.756440 SipDialogController::processResponseOutsideDialog
2022-03-23 02:05:24.756466 tport.c:1157 tport_ref() tport_ref(0x55e385530920): refcount is now 5
2022-03-23 02:05:24.756493 tport.c:1170 tport_unref() tport_unref(0x55e385530920): refcount is now 4
2022-03-23 02:05:24.756578 ClientController::removeAppTransaction: transactionId 4cb71bdf-fdcc-416e-bb81-91fa669ad0a3; size: 0
2022-03-23 02:05:24.756617 No connected clients found to handle incoming cdr:stop request
2022-03-23 02:05:24.756652 ClientController::removeDialog - dialog not found: 781995d1-24f0-123b-50bd-0242ac110002;from-tag=m4tecSQ9y9aUB
2022-03-23 02:05:24.756673 SipDialog::~SipDialog - destroying sip dialog with call-id 781995d1-24f0-123b-50bd-0242ac110002
2022-03-23 02:05:24.756696 nta.c:4630 nta_leg_destroy() nta_leg_destroy(0x55e385532e60)
2022-03-23 02:05:24.756718 tport.c:1170 tport_unref() tport_unref(0x55e385530920): refcount is now 3
2022-03-23 02:05:24.756766 SipDialog::~SipDialog - destroying orq from original (uac) INVITE 0x55e385533a20
2022-03-23 02:05:24.756796 nta.c:8899 outgoing_free() nta: outgoing_free(0x55e385533a20)
2022-03-23 02:05:24.756856 Client::write_handler - wrote 471 bytes: system:0
2022-03-23 02:05:24.757779 tport.c:1170 tport_unref() tport_unref(0x55e385530920): refcount is now 2
2022-03-23 02:05:24.757817 Client::read_handler read: b0fb35a1-2afd-41e0-b3c9-6791920a1b9a|sip||781995d1-24f0-123b-50bd-0242ac110002;from-tag=m4tecSQ9y9aUB
ACK sip:[email protected]:5038 SIP/2.0
Content-Length: 0
2022-03-23 02:05:24.757854 nta.c:9106 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 0/1 free
2022-03-23 02:05:24.757884 Client::processMessage - got request with 4 tokens
2022-03-23 02:05:24.757886 nta.c:1350 agent_timer() nta: timer not set
2022-03-23 02:05:24.757924 Client::processMessage - request id b0fb35a1-2afd-41e0-b3c9-6791920a1b9a, request type: sip transaction id: , dialog id: 781995d1-24f0-123b-50bd-0242ac110002;from-tag=m4tecSQ9y9aUB
2022-03-23 02:05:24.757952 Client::processMessage - sending a request inside a dialog (dialogId provided)
2022-03-23 02:05:24.757995 ClientController::addApiRequest: clientMsgId b0fb35a1-2afd-41e0-b3c9-6791920a1b9a; size: 1
2022-03-23 02:05:24.758069 SipDialogController::doSendRequestInsideDialog dialog id: 781995d1-24f0-123b-50bd-0242ac110002;from-tag=m4tecSQ9y9aUB
2022-03-23 02:05:24.758113 Can't send ACK for dialog id 781995d1-24f0-123b-50bd-0242ac110002;from-tag=m4tecSQ9y9aUB; likely because stack already ACK'ed non-success final response
2022-03-23 02:05:24.758155 SipDialogController::doSendRequestInsideDialog - Error: ACK for non-success final response is automatically generated by server
2022-03-23 02:05:24.758184 ClientController::removeApiRequest: clientMsgId b0fb35a1-2afd-41e0-b3c9-6791920a1b9a; size: 0
2022-03-23 02:05:24.758222 ClientController::removeAppTransaction: transactionId 98f57143-2c33-4547-bd6e-261b0fe0ca42; size: 0
2022-03-23 02:05:24.758335 Client::write_handler - wrote 176 bytes: system:0
2022-03-23 02:05:24.758400 Client::read_handler read: 8e5f8e46-2e60-4e0e-ad9d-629f3e95ce30|sip|8be42c7b-34cc-4265-9570-1837e0d4b451|
SIP/2.0 603 Decline
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
cseq: 2 INVITE
from: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
to: <sip:[email protected]:5061>
Content-Length: 0
2022-03-23 02:05:24.758449 Client::processMessage - got request with 4 tokens
2022-03-23 02:05:24.758475 Client::processMessage - request id 8e5f8e46-2e60-4e0e-ad9d-629f3e95ce30, request type: sip transaction id: 8be42c7b-34cc-4265-9570-1837e0d4b451, dialog id:
2022-03-23 02:05:24.758501 ClientController::addApiRequest: clientMsgId 8e5f8e46-2e60-4e0e-ad9d-629f3e95ce30; size: 1
2022-03-23 02:05:24.758579 SipDialogController::doRespondToSipRequest thread 140074811344192
2022-03-23 02:05:24.758619 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 8be42c7b-34cc-4265-9570-1837e0d4b451
2022-03-23 02:05:24.758641 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId 8be42c7b-34cc-4265-9570-1837e0d4b451, most likely this is a response to an invite we sent
2022-03-23 02:05:24.758745 pending-request: removing entry, prior to removal length: 1
2022-03-23 02:05:24.758772 pending-request: removed entry, timer not set (queue is empty after removal), length: 0
2022-03-23 02:05:24.758809 nta.c:1411 set_timeout() nta: timer set to 2000 ms
2022-03-23 02:05:24.758835 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 2
2022-03-23 02:05:24.758869 nta.c:4577 nta_leg_tcreate() nta_leg_tcreate(0x55e38554e290)
2022-03-23 02:05:24.758890 DrachtioController::setupLegForIncomingRequest - created leg: 0x55e38554e290, irq: 0x55e385532b20, for transactionId: 8be42c7b-34cc-4265-9570-1837e0d4b451, tag:
2022-03-23 02:05:24.758915 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 3
2022-03-23 02:05:24.758949 SipDialog::SipDialog - creating dialog for inbound INVITE sent from TLS/99.47.182.46:63097
2022-03-23 02:05:24.758980 adding IIP for incoming call tid:8be42c7b-34cc-4265-9570-1837e0d4b451 alive:0s leg:0x55e38554e290 irq:0x55e385532b20 orq:0 rel:0
2022-03-23 02:05:24.759008 IIP_Insert incoming - ref count: 1 inserting tid:8be42c7b-34cc-4265-9570-1837e0d4b451 alive:0s leg:0x55e38554e290 irq:0x55e385532b20 orq:0 rel:0
2022-03-23 02:05:24.759048 SipDialogController::doRespondToSipRequest found invite or subscribe in progress 0x55e385535710
2022-03-23 02:05:24.759073 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:05:24.759101 SipTransport::getContactUri - created Contact header: sips:104.131.19.169:5061;transport=tls
2022-03-23 02:05:24.759128 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:05:24.759381 makeTags - Adding well-known header 'Call-ID' with value '566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C'
2022-03-23 02:05:24.759416 makeTags - Adding well-known header 'cseq' with value '2 INVITE'
2022-03-23 02:05:24.759445 makeTags - Adding well-known header 'from' with value '<sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91'
2022-03-23 02:05:24.759474 makeTags - Adding well-known header 'to' with value '<sip:[email protected]:5061>'
2022-03-23 02:05:24.759507 Sending 603 response (not reliably) on irq 0x55e385532b20
2022-03-23 02:05:24.759551 tport.c:3285 tport_tsend() tport_tsend(0x55e385513e90) tpn = TLS/99.47.182.46:63097
2022-03-23 02:05:24.759656 tport_type_tls.c:594 tport_tls_send() tport_tls_writevec: vec 0x55e385523530 0x55e385516260 341 (341)
2022-03-23 02:05:24.759686 tport.c:3534 tport_send_msg() tport_vsend returned 341
2022-03-23 02:05:24.759779 send 341 bytes to tls/[99.47.182.46]:63097 at 02:05:24.759581:
SIP/2.0 603 Decline
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKdNOa427pBsQoGcYl;rport=63097;received=99.47.182.46
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>;tag=ppD0FFSgSUQ0j
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
CSeq: 2 INVITE
Content-Length: 0
2022-03-23 02:05:24.759813 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:05:24.759839 nta.c:6950 incoming_reply() nta: sent 603 Decline for INVITE (2)
2022-03-23 02:05:24.759863 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:05:24.759885 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:05:24.759917 ClientController::removeApiRequest: clientMsgId 8e5f8e46-2e60-4e0e-ad9d-629f3e95ce30; size: 0
2022-03-23 02:05:24.759955 No connected clients found to handle incoming cdr:stop request
2022-03-23 02:05:24.759979 ClientController::removeNetTransaction: transactionId 8be42c7b-34cc-4265-9570-1837e0d4b451; size: 0
2022-03-23 02:05:24.760132 Client::write_handler - wrote 619 bytes: system:0
2022-03-23 02:05:24.869441 tport.c:2801 tport_wakeup() tport_wakeup(0x55e385513e90): events IN
2022-03-23 02:05:24.869583 tport.c:2892 tport_recv_event() tport_recv_event(0x55e385513e90)
2022-03-23 02:05:24.869608 tport_type_tls.c:491 tport_tls_recv() tport_tls_recv(0x55e385513e90): tls_read() returned 373
2022-03-23 02:05:24.869636 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55e385513e90) msg 0x55e38553d2a0 from (tls/99.47.182.46:63097) has 373 bytes, veclen = 1
2022-03-23 02:05:24.869801 recv 373 bytes from tls/[99.47.182.46]:63097 at 02:05:24.869661:
ACK sip:[email protected]:5061 SIP/2.0
Via: SIP/2.0/TLS 192.168.86.42:63097;branch=z9hG4bKdNOa427pBsQoGcYl;rport
Max-Forwards: 70
Call-ID: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
From: <sip:[email protected]:5061>;tag=53B086C53DC49F7A93A59F123EB1AE91
To: <sip:[email protected]:5061>;tag=ppD0FFSgSUQ0j
CSeq: 2 ACK
User-Agent: VIDA/0.0.6
Content-Length: 0
2022-03-23 02:05:24.869840 tport.c:3051 tport_deliver() tport_deliver(0x55e385513e90): msg 0x55e38553d2a0 (373 bytes) from tls/99.47.182.46:63097 next=(nil)
2022-03-23 02:05:24.869861 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 4
2022-03-23 02:05:24.869886 nta.c:3039 agent_recv_request() nta: received ACK sip:[email protected]:5061 SIP/2.0 (CSeq 2)
2022-03-23 02:05:24.869915 nta.c:3334 agent_check_request_via() nta: Via check: received=99.47.182.46
2022-03-23 02:05:24.869950 nta.c:3178 agent_recv_request() nta: ACK (2) is going to INVITE (2)
2022-03-23 02:05:24.869973 SipDialogController::processCancelOrAck: ACK
2022-03-23 02:05:24.870025 SipDialogController::clearSipTimers for 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
2022-03-23 02:05:24.870061 tport.c:1157 tport_ref() tport_ref(0x55e385513e90): refcount is now 5
2022-03-23 02:05:24.870086 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 4
2022-03-23 02:05:24.870116 ClientController::route_ack_request_inside_dialog - client managing dialog has disconnected, or the call was rejected as part of outbound request handler: 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C;from-tag=53B086C53DC49F7A93A59F123EB1AE91
2022-03-23 02:05:24.870142 SipDialog::~SipDialog - destroying sip dialog with call-id 566837E2842EE2BE0C863CDC2A7F5D0F0D49E32C
2022-03-23 02:05:24.870167 nta.c:4630 nta_leg_destroy() nta_leg_destroy(0x55e38554e290)
2022-03-23 02:05:24.870192 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 3
2022-03-23 02:05:24.870230 nta.c:5903 incoming_free() nta: incoming_free(0x55e385532b20)
2022-03-23 02:05:24.870255 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 2
2022-03-23 02:05:24.870294 tport.c:1170 tport_unref() tport_unref(0x55e385513e90): refcount is now 1
2022-03-23 02:05:24.870315 tport.c:2324 tport_set_secondary_timer() tport(0x55e385513e90): reset timer
2022-03-23 02:05:26.761313 nta.c:1350 agent_timer() nta: timer not set
If helpful, here is the docker command I run to start the drachtio-server container. Perhaps I'm doing something bad with my contacts?
sudo docker run -d --rm --name drachtio -v /xx/xx/xx/xx.xx/cert/xx/xx.xx -v /xx/xx/xx/xx.xx:/xx/xx/xx.xx -p 5060:5060/udp -p 5060:5060/tcp -p 9022:9022/udp -p 9022:9022/tcp -p 5061:5061/udp -p 5061:5061/tcp -p 7443:7443/tcp drachtio/drachtio-server:0.8.8 drachtio --contact "sip:*;transport=udp,tcp,ws" --external-ip "104.131.19.169" --contact "sips:*:5061;transport=tls" --external-ip "104.131.19.169" --contact "sips:*:7443;transport=wss" --external-ip "104.131.19.169" --key-file /xx/xx/xx.xx/xx.xx --cert-file /xx/xx/xx.xx/xx.xx --chain-file /xx/xx/xx.xx/xx.xx--dh-param /xx/xx/xx.xx/xx.xx
looks like drachtio server tries to send an invite to freeswitch at 104.131.19.169:5038 and there is no response. Are you sure there is a freeswitch listening for tcp at that address:port? If so, you should check the logs on the freeswitch to see if you see the invite coming in
2022-03-23 02:04:52.748893 send 1528 bytes to tcp/[104.131.19.169]:5038 at 02:04:52.748509:
INVITE sip:[email protected]:5038 SIP/2.0
Yeah, FS is listening there. It works on the first Invite to FS, but all subsequents fail until I restart Drachtio on anything > 0.8.8.
OK, I do get the INVITE on Freeswitch, but it doesn't do anything at all with it. I never saw it before because I didn't have sip trace enabled on the FS profile. Weird!
BAD INVITE (on FS) (v0.8.11):
freeswitch@east1> show channels
0 total.
recv 1528 bytes from tcp/[172.17.0.2]:33597 at 03:19:39.673126:
------------------------------------------------------------------------
INVITE sip:[email protected]:5038 SIP/2.0
Via: SIP/2.0/UDP 104.131.19.169;rport;branch=z9hG4bKU8K11U38SD20S
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=6966tyZHZXFtB
To: <sip:[email protected]:5038>
Call-ID: ea83fdee-24fa-123b-4998-0242ac110002
CSeq: 49448997 INVITE
Contact: <sip:104.131.19.169:5060>
User-Agent: drachtio-fsmrf:ed69ddf4-f0e1-400f-8935-b9a40be8ff9a
Content-Type: application/sdp
Content-Length: 1040
X-esl-outbound: 104.131.19.169:8099
v=0
o=- 6848199707 32336 IN IP4 104.131.19.169
s=hvdzise
c=IN IP4 104.131.19.169
t=0 0
m=audio 20282 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20283
a=ptime:20
m=audio 20306 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20307
a=ptime:20
m=video 20326 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20327
m=video 20350 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20351
** GOOD invite (v0.8.8) (same FS instance without a restart) **
recv 1528 bytes from tcp/[172.17.0.2]:53689 at 03:23:16.164436:
------------------------------------------------------------------------
INVITE sip:[email protected]:5038 SIP/2.0
Via: SIP/2.0/TCP 104.131.19.169;rport;branch=z9hG4bK49Bttr4v1Qr4B
Max-Forwards: 70
From: <sip:104.131.19.169:5060>;tag=DaSyF49S8Zy7K
To: <sip:[email protected]:5038>
Call-ID: 6b8dee0d-24fb-123b-4294-0242ac110002
CSeq: 49449106 INVITE
Contact: <sip:104.131.19.169:5060>
User-Agent: drachtio-fsmrf:40f821b2-56e4-41b0-91dc-d6a635809f89
Content-Type: application/sdp
Content-Length: 1040
X-esl-outbound: 104.131.19.169:8099
v=0
o=- 6986003574 31450 IN IP4 104.131.19.169
s=byxlesd
c=IN IP4 104.131.19.169
t=0 0
m=audio 20502 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20503
a=ptime:20
m=audio 20542 RTP/AVP 103 0 101
a=rtpmap:103 opus/48000/2
a=fmtp:103 maxplaybackrate=16000;maxaveragebitrate=24000;useinbandfec=1;usedtx=1
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=rtcp:20543
a=ptime:20
m=video 20576 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20577
m=video 20608 RTP/AVP 99 108
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d;packetization-mode=1;level-asymmetry-allowed=1
a=rtpmap:108 VP8/90000
a=fmtp:108 max-fr=30;max-fs=3600
a=sendrecv
a=rtcp:20609
2022-03-23 03:23:16.161411 [NOTICE] switch_channel.c:1118 New Channel sofia/drachtio_mrf/[email protected]:5060 [babe64b7-240d-4203-8a05-7fe0a99a4e43]
2022-03-23 03:23:16.161411 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->drachtio in context mrf
send 321 bytes to tcp/[172.17.0.2]:53689 at 03:23:16.165586:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 104.131.19.169;rport=53689;branch=z9hG4bK49Bttr4v1Qr4B;received=172.17.0.2
From: <sip:104.131.19.169:5060>;tag=DaSyF49S8Zy7K
To: <sip:[email protected]:5038>
Call-ID: 6b8dee0d-24fb-123b-4294-0242ac110002
CSeq: 49449106 INVITE
User-Agent: drachtio mrf
Content-Length: 0
EXECUTE [depth=0] sofia/drachtio_mrf/[email protected]:5060 answer()
2022-03-23 03:23:16.161411 [NOTICE] avcodec.c:1431 codec: id=27 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2022-03-23 03:23:16.161411 [NOTICE] avcodec.c:1431 codec: id=27 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2022-03-23 03:23:16.161411 [INFO] switch_core_media.c:9576 Activating VIDEO RTCP PORT 20609 interval 1000 mux -1
2022-03-23 03:23:16.161411 [NOTICE] sofia_media.c:92 Pre-Answer sofia/drachtio_mrf/[email protected]:5060!
2022-03-23 03:23:16.161411 [NOTICE] mod_dptools.c:1406 Channel [sofia/drachtio_mrf/[email protected]:5060] has been answered
any thoughts on the above? I can't figure out why it's happening. There's no difference in the FS version between these invites. Only difference is the Drachtio server version. It seems docker networking/nat related if I had to guess.