Hello,
I am very new to Asterisk and using it with chan_sip. In my dial plan, when peer1 dials an extension to call peer2, The Dial application sets the DIALSTATUS variable to NOANSWER, BUSY, etc. depending on state of peer2. How can I let peer1 know or receive the value written in DIALSTATUS (so it may know that the other party is busy and display a message for example)? Thanks.
I think you mean ${HANGUPCAUSE}!
Simply dropping off the end of the dialpan, or calling hHangup, with no parameters, will do this, providing you haven’t previously sent a status. A common mistake is to answer calls before calling Dial, which will send an answered status.
This assumes that your channel technology supports hangup causes.
Do you mean Asterisk will send a SIP message back to the caller to inform it that the callee is busy for instance and that the client is supposed to be able to read that message to know dial op return status?
It will only send a SIP message (final response code) if the caller is using SIP.
If Asterisk were primarily SIP, it would return exactly the same message that Asterisk had received and which made Asterisk believe that the callee was busy.
As Asterisk is more of an ISDN switch with SIP bolted on, the SIP message will be translated to an ISDN cause code and then translated back, which may result in a different status.
For example, if the callee replies 486, asterisk will translate this to AST_CAUSE_BUSY, and then back to 486.
So normally, a SIP client could possibly be able to receive and interpret such a response to learn that the callee was busy for instance, correct?
SIP response codes which terminate the call attempt in that case can provide additional information, such as that they are busy. There are also headers which can provide the underlying ISDN cause code. It’s up to the client to use the information and present it to the user in some manner. Playing busy tone for example.
Indeed. A callback function is being called in our SIP client with the returned reason (e.g. busy) but it is taking up to 12 seconds to be called. Why is Asterisk taking so long to respond? Other servers (e.g. Linphone) report busy state immediately (in less than two seconds). Is there any setting or tweak to shorten that call response delay? By the way, the same delay is observed when callee declines the call.
sip.conf
allowguest=no
alwaysauthreject=yes
srvlookup=no
udpbindaddr=0.0.0.0
tcpenable=no
canreinvite=no
dtmfmode=auto
nat=force_rport,comedia
directrtpsetup=yes
callevents=yes
callcounter=yes
notifyhold = yes
rtcachefriends=yes
busylevel=1
Would also post the log…
Thanks
You would need to provide verbose level 5 logs from the actual log file (not a console screen scrape) to get a better idea, but 12 seconds sounds like a DNS configuration error, resulting in a timeout, rather than a no such domain response. Soft phones probably don’t do, in particular, reverse DNS lookups.
But servers others than Asterisk are responding much quickly on same (DNS) config.
You only quoted Linphone and that is a phone, and pure server, when on the B side of a call. As a server, it doesn’t really need to do any DNS lookups. On a normal call, Asterisk is both client and server, and may need to reverse roles on the A side. In sum, Asterisk needs valid forward and reverse name resolution for all addresses and domain names in use, and if you don’t have that, 12 seconds is a typical DNS timeout.
Providing the logs will give a better idea of at what stage in the call Asterisk is being stalled.
Of course, you can also write dialplans that produce delays, even after the B side has failed, and again the logs will confirm that you haven’t done that.
Could you please explain a bit more how Asterisk and Linphone could be different? I don’t quite understand why Linphone is only a server while Asterisk has to be both client and server. Is it a design difference? Eventually, can anything be done to solve or reduce this DNS issue, knowing that Asterisk is on a public IP and the SIP phones behind NAT on WIFI.
For some reason the logger is not writing to the file. Working on it…
When acting as the B side, Linphone receives INVITEs and generates responses, so it is a server.
When Asterisk acts as a PABX, it receives INVITEs, (as a server), then generates INVITEs to the B side (as a client). It also quite often generates Re-INVITEs to the A side (also as a client).
Setting up DNS properly is really outside the scope of Asterisk, as there is nothing Asterisk specific about it You can often use /etc/hosts, instead.
However, without the logs, and possible some further logging, it is just the value of 12 seconds that sounds a about right for broken DNS. The misconfiguration may be elsewhere.
Actually, our Asterisk is on a public IP so there should be no domain resolution issues involved. I still don’t understand why Linphone act as a server only while Asterisk has to be both client and server. Is it by design?
Here’s the log [part 1] in which peer C is trying to call peer A who is busy:
<------------->
[2017-08-12 11:15:04] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:52589 --->
INVITE sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjeb151a3b-984b-4ee0-9029-8d5d8ba6eafe
Max-Forwards: 70
f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
t: sip:PEERA@XXX.XXX.XXX.XXX
m: <sip:PEERC@XXX.XXX.XXX.YYY:52589;ob>
i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26212 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Test Android 2.6
c: application/sdp
l: 483
v=0
o=- 3711518103 3711518103 IN IP4 XXX.XXX.XXX.ZZZ
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 40923 RTP/AVP 99 98 9 104 97 3 18 8 0 96
c=IN IP4 XXX.XXX.XXX.ZZZ
b=TIAS:64000
b=RS:0
b=RR:0
a=sendrecv
a=rtpmap:99 speex/32000
a=rtpmap:98 speex/16000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:97 speex/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ice-ufrag:3f5c529c
a=ice-pwd:2873b448
a=candidate:Hac100e27 1 UDP 2130706431 XXX.XXX.XXX.ZZZ 40923 typ host
<------------->
<--- Reliably Transmitting (NAT) to XXX.XXX.XXX.YYY:52589 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;branch=z9hG4bKPjeb151a3b-984b-4ee0-9029-8d5d8ba6eafe;received=XXX.XXX.XXX.YYY;rport=52589
From: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
To: sip:PEERA@XXX.XXX.XXX.XXX;tag=as7b4e129b
Call-ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26212 INVITE
Server: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6e1febf8"
Content-Length: 0
<------------>
[2017-08-12 11:15:04] DEBUG[15018][C-0000004a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #986
[2017-08-12 11:15:04] DEBUG[15018][C-0000004a] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for XXX.XXX.XXX.YYY:52589
[2017-08-12 11:15:04] VERBOSE[15018][C-0000004a] chan_sip.c: Scheduling destruction of SIP dialog '64b5f9a6-0b7e-4a38-a37d-747005234d5b' in 32000 ms (Method: INVITE)
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:52589 --->
ACK sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjeb151a3b-984b-4ee0-9029-8d5d8ba6eafe
Max-Forwards: 70
f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
t: sip:PEERA@XXX.XXX.XXX.XXX;tag=as7b4e129b
i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26212 ACK
l: 0
<------------->
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 0 [ 56]: ACK sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 1 [ 94]: v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjeb151a3b-984b-4ee0-9029-8d5d8ba6eafe
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 3 [ 69]: f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 4 [ 43]: t: sip:PEERA@XXX.XXX.XXX.XXX;tag=as7b4e129b
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 5 [ 39]: i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 6 [ 15]: CSeq: 26212 ACK
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 7 [ 4]: l: 0
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c: --- (8 headers 0 lines) ---
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: = Looking for Call ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b (Checking From) --From tag e0372590-c4bb-4909-a156-0f83642b5f78 --To-tag as7b4e129b
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #986
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Stopping retransmission on '64b5f9a6-0b7e-4a38-a37d-747005234d5b' of Response 26212: Match Found
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:52589 --->
INVITE sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0
Max-Forwards: 70
f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
t: sip:PEERA@XXX.XXX.XXX.XXX
m: <sip:PEERC@XXX.XXX.XXX.YYY:52589;ob>
i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26213 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Test Android 2.6
Authorization: Digest username="PEERC", realm="asterisk", nonce="6e1febf8", uri="sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP", response="367d0b1bf0108f6cec253a668268b9c1", algorithm=MD5
c: application/sdp
l: 483
v=0
o=- 3711518103 3711518103 IN IP4 XXX.XXX.XXX.ZZZ
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 40923 RTP/AVP 99 98 9 104 97 3 18 8 0 96
c=IN IP4 XXX.XXX.XXX.ZZZ
b=TIAS:64000
b=RS:0
b=RR:0
a=sendrecv
a=rtpmap:99 speex/32000
a=rtpmap:98 speex/16000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:97 speex/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ice-ufrag:3f5c529c
a=ice-pwd:2873b448
a=candidate:Hac100e27 1 UDP 2130706431 XXX.XXX.XXX.ZZZ 40923 typ host
<------------->
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 0 [ 59]: INVITE sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 1 [ 94]: v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 3 [ 69]: f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 4 [ 28]: t: sip:PEERA@XXX.XXX.XXX.XXX
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 5 [ 42]: m: <sip:PEERC@XXX.XXX.XXX.YYY:52589;ob>
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 6 [ 39]: i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 7 [ 18]: CSeq: 26213 INVITE
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 8 [ 38]: k: replaces, 100rel, timer, norefersub
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 9 [ 7]: x: 1800
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 10 [ 10]: Min-SE: 90
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 11 [ 32]: User-Agent: Test Android 2.6
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 12 [190]: Authorization: Digest username="PEERC", realm="asterisk", nonce="6e1febf8", uri="sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP", response="367d0b1b845d8f6cec253a668268b9c1", algorithm=MD5
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 13 [ 18]: c: application/sdp
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 14 [ 6]: l: 483
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 15 [ 0]:
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 0 [ 3]: v=0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 1 [ 45]: o=- 3711518103 3711518103 IN IP4 XXX.XXX.XXX.ZZZ
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 2 [ 9]: s=pjmedia
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 3 [ 7]: b=AS:84
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 4 [ 5]: t=0 0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 5 [ 9]: a=X-nat:0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 6 [ 48]: m=audio 40923 RTP/AVP 99 98 9 104 97 3 18 8 0 96
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 7 [ 21]: c=IN IP4 XXX.XXX.XXX.ZZZ
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 8 [ 12]: b=TIAS:64000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 9 [ 6]: b=RS:0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 10 [ 6]: b=RR:0
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 11 [ 10]: a=sendrecv
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 12 [ 23]: a=rtpmap:99 speex/32000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 13 [ 23]: a=rtpmap:98 speex/16000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 14 [ 22]: a=rtpmap:104 iLBC/8000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 15 [ 18]: a=fmtp:104 mode=30
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 16 [ 22]: a=rtpmap:97 speex/8000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 17 [ 32]: a=rtpmap:96 telephone-event/8000
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 18 [ 14]: a=fmtp:96 0-16
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 19 [ 20]: a=ice-ufrag:3f5c529c
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 20 [ 18]: a=ice-pwd:2873b448
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Body 21 [ 66]: a=candidate:Hac100e27 1 UDP 2130706431 XXX.XXX.XXX.ZZZ 40923 typ host
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c: --- (15 headers 22 lines) ---
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: = Looking for Call ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b (Checking From) --From tag e0372590-c4bb-4909-a156-0f83642b5f78 --To-tag
[2017-08-12 11:15:05] DEBUG[15018] netsock2.c: Splitting 'XXX.XXX.XXX.XXX:5060' into...
[2017-08-12 11:15:05] DEBUG[15018] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port '5060'.
[2017-08-12 11:15:05] DEBUG[15018] netsock2.c: Splitting 'XXX.XXX.XXX.XXX:5060' into...
[2017-08-12 11:15:05] DEBUG[15018] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port '5060'.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.YYY:52589' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.YYY' and port '52589'.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Sending to XXX.XXX.XXX.YYY:52589 (NAT)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Initializing initreq for method INVITE - callid 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Using INVITE request as basis request - 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found peer 'PEERC' for 'PEERC' from XXX.XXX.XXX.YYY:52589
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fde8c099988'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Allocated port 14316 for RTP instance '0x7fde8c099988'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 ICE session created, comp_cnt=2, role is Unknown agent
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 Candidate 0 added: comp_id=1, type=host, foundation=H95051561, addr=XXX.XXX.XXX.XXX:14316, base=XXX.XXX.XXX.XXX:14316, prio=0x7effffff (2130706431)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: RTP instance '0x7fde8c099988' is setup and ready to go
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 Destroying ICE session 0x7fde8c057f08
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c087fc8 destroy request, ref_cnt=4
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c0ba348 destroy request, ref_cnt=3
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: ice_session.c ICE session 0x7fde8c057f08 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c087fc8 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c0ba348 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fde8c002ba8'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Allocated port 18826 for RTP instance '0x7fde8c002ba8'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 ICE session created, comp_cnt=2, role is Unknown agent
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 Candidate 0 added: comp_id=1, type=host, foundation=H95051561, addr=XXX.XXX.XXX.XXX:18826, base=XXX.XXX.XXX.XXX:18826, prio=0x7effffff (2130706431)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: RTP instance '0x7fde8c002ba8' is setup and ready to go
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: icess0x7fde8c0 Destroying ICE session 0x7fde8c057f08
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c0889c8 destroy request, ref_cnt=4
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c046f28 destroy request, ref_cnt=3
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: ice_session.c ICE session 0x7fde8c057f08 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c0889c8 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c046f28 destroyed
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fde8c002ba8'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fde8c099988'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Setting NAT on RTP to On
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Setting NAT on VRTP to On
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP o=- 3711518103 3711518103 IN IP4 XXX.XXX.XXX.ZZZ... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 99
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 99 (0x7fde8c0c0508) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 98
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 98 (0x7fde8c0c0d48) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 9
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 9 (0x7fde8c0c1588) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 104
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 104 (0x7fde8c0a5e38) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 97
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 97 (0x7fde8c0a6678) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 3
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 3 (0x7fde8c0a6eb8) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 18
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 18 (0x7fde8c0a76f8) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 8 (0x7fde8c0a7f38) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 0
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 0 (0x7fde8c0a8a38) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found RTP audio format 96
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Setting payload 96 (0x7fde8c0a9278) based on m type on 0x7fde5e88bbf0
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.ZZZ' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.ZZZ' and port ''.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 XXX.XXX.XXX.ZZZ... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP b=RS:0... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP b=RR:0... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found audio description format speex for ID 99
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:99 speex/32000... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found audio description format speex for ID 98
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 speex/16000... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found audio description format iLBC for ID 104
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 iLBC/8000... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:104 mode=30... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found audio description format speex for ID 97
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 speex/8000... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Found audio description format telephone-event for ID 96
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-16... UNSUPPORTED OR FAILED.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:3f5c529c... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:2873b448... OK.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.ZZZ' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.ZZZ' and port ''.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Processing media-level (audio) SDP a=candidate:Hac100e27 1 UDP 2130706431 XXX.XXX.XXX.ZZZ 40923 typ host... OK.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Capabilities: us - (speex|ilbc|g722|g729|h264), peer - audio=(ulaw|gsm|alaw|g722|g729|speex|speex16|speex32|ilbc)/video=(nothing)/text=(nothing), combined - (speex|ilbc|g722|g729)
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c099988'
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Peer audio RTP is at port XXX.XXX.XXX.ZZZ:40923
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 0 (0x7fde8c0a8a38) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 3 (0x7fde8c0a6eb8) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 8 (0x7fde8c0a7f38) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 9 (0x7fde8c0c1588) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 18 (0x7fde8c0a76f8) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 96 (0x7fde8c0a6678) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 97 (0x7fde8c0a5e38) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 98 (0x7fde8c0c0508) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 99 (0x7fde8c08ac68) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] rtp_engine.c: Copying payload 104 (0x7fde8c0c0d48) from 0x7fde5e88bbf0 to 0x7fde8c099ac8
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fde8c099988'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c002ba8'
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Peer doesn't provide video
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: We're settling with these formats: (speex|ilbc|g722|g729)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Checking SIP call limits for device PEERC
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Updating call counter for incoming call
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Call from peer 'PEERC' is 1 out of 2147483647
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERC
[2017-08-12 11:15:05] DEBUG[14986] chan_sip.c: Checking device state for peer PEERC
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: Changing state for SIP/PEERC - state 2 (In use)
[2017-08-12 11:15:05] DEBUG[15052] app_queue.c: Device 'SIP/PEERC' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX:5060' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Looking for PEERA in sip-ctx (domain XXX.XXX.XXX.XXX)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Incoming INVITE with 'timer' option supported
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: INVITE also has "Session-Expires" header.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Session-Expires: 1800
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: INVITE also has "Min-SE" header.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Received Min-SE: 90
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: *** Our native formats are (speex)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: *** Joint capabilities are (speex|ilbc|g722|g729)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: *** Our capabilities are (speex|ilbc|g722|g729|h264)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: *** AST_CODEC_CHOOSE formats are speex
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: This channel can handle video! HOLLYWOOD next!
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] sip/route.c: sip_route_dump: route/path hop: <sip:PEERC@XXX.XXX.XXX.YYY:52589;ob>
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: SIP/PEERC-0000002f: New call is still down.... Trying...
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c:
<--- Transmitting (NAT) to XXX.XXX.XXX.YYY:52589 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0;received=XXX.XXX.XXX.YYY;rport=52589
From: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
To: sip:PEERA@XXX.XXX.XXX.XXX
Call-ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26213 INVITE
Server: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:PEERA@XXX.XXX.XXX.XXX:5060>
Content-Length: 0
<------------>
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for XXX.XXX.XXX.YYY:52589
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERC
[2017-08-12 11:15:05] DEBUG[14986] chan_sip.c: Checking device state for peer PEERC
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: Changing state for SIP/PEERC - state 2 (In use)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pbx.c: Result of 'EXTEN' is 'PEERA'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: ```Log part 2:
Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] app_stack.c: Channel SIP/PEERC-0000002f has no datastore, so we're allocating one.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] app_stack.c: Setting 'ARG1' to 'PEERA'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pbx.c: Result of 'ARG1' is 'PEERA'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Asked to create a SIP channel with formats: (speex)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Allocating new SIP dialog for 4865c8547ed10e480de9d7691aecd73e@172.16.13.192:5060 - INVITE (No RTP)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fde8c007128'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Allocated port 17254 for RTP instance '0x7fde8c007128'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 ICE session created, comp_cnt=2, role is Unknown agent
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 Candidate 0 added: comp_id=1, type=host, foundation=H95051561, addr=XXX.XXX.XXX.XXX:17254, base=XXX.XXX.XXX.XXX:17254, prio=0x7effffff (2130706431)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] rtp_engine.c: RTP instance '0x7fde8c007128' is setup and ready to go
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 Destroying ICE session 0x7fde8c057f08
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c084728 destroy request, ref_cnt=4
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c0ba978 destroy request, ref_cnt=3
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: ice_session.c ICE session 0x7fde8c057f08 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c084728 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c0ba978 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Allocated port 11024 for RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 ICE session created, comp_cnt=2, role is Unknown agent
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into...
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 Candidate 0 added: comp_id=1, type=host, foundation=H95051561, addr=XXX.XXX.XXX.XXX:11024, base=XXX.XXX.XXX.XXX:11024, prio=0x7effffff (2130706431)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] rtp_engine.c: RTP instance '0x7fde8c01fdc8' is setup and ready to go
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: icess0x7fde8c0 Destroying ICE session 0x7fde8c057f08
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c084728 destroy request, ref_cnt=4
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stuse0x7fde8c0 STUN session 0x7fde8c0ba978 destroy request, ref_cnt=3
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: ice_session.c ICE session 0x7fde8c057f08 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c084728 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] pjsip: stun_session.c STUN session 0x7fde8c0ba978 destroyed
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fde8c007128'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Setting NAT on RTP to On
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Setting NAT on VRTP to On
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] acl.c: For destination 'XXX.XXX.XXX.YYY', our source address is 'XXX.XXX.XXX.XXX'.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Setting AST_TRANSPORT_UDP with address XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Setting NAT on RTP to On
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Setting NAT on VRTP to On
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: SIP call-id changed from '4865c8547ed10e480de9d7691aecd73e@172.16.13.192:5060' to '447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** Our native formats are (speex)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** Joint capabilities are (speex)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** Our capabilities are (speex|ilbc|g722|g729|h264)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** AST_CODEC_CHOOSE formats are speex
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** Our preferred formats from the incoming channel are (speex)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: This channel can handle video! HOLLYWOOD next!
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] channel_internal_api.c: Channel Call ID changing from [C-0000004a] to [C-0000004a]
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Outgoing Call for PEERA
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Updating call counter for outgoing call
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Call to peer 'PEERA' is 2 out of 2147483647
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERA
[2017-08-12 11:15:05] DEBUG[14986] chan_sip.c: Checking device state for peer PEERA
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: Changing state for SIP/PEERA - state 7 (Ring+Inuse)
[2017-08-12 11:15:05] DEBUG[15052] app_queue.c: Device 'SIP/PEERA' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: This call needs video offers!
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: ** Our capability: (speex|ilbc|g722|g729|h264) Video flag: False Text flag: False
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: ** Our prefcodec: (speex)
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Audio is at 17254
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Video is at XXX.XXX.XXX.XXX:11024
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding codec speex to SDP
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding codec ilbc to SDP
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding codec g722 to SDP
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding codec g729 to SDP
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding video codec h264 to SDP
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: -- Done with adding codecs to SDP
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Done building SDP. Settling with this capability: (speex|ilbc|g722|g729|h264)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Initializing initreq for method INVITE - callid 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 0 [ 52]: INVITE sip:PEERA@XXX.XXX.XXX.YYY:57737;ob SIP/2.0
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK1525636e;rport
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 3 [ 48]: From: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 4 [ 43]: To: <sip:PEERA@XXX.XXX.XXX.YYY:57737;ob>
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 5 [ 41]: Contact: <sip:PEERC@XXX.XXX.XXX.XXX:5060>
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 6 [ 58]: Call-ID: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 8 [ 49]: User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 9 [ 35]: Date: Sat, 12 Aug 2017 09:15:05 GMT
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp
[2017-08-12 11:15:05] VERBOSE[15632][C-0000004a] chan_sip.c: Reliably Transmitting (NAT) to XXX.XXX.XXX.YYY:57737:
INVITE sip:PEERA@XXX.XXX.XXX.YYY:57737;ob SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK1525636e;rport
Max-Forwards: 70
From: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
To: <sip:PEERA@XXX.XXX.XXX.YYY:57737;ob>
Contact: <sip:PEERC@XXX.XXX.XXX.XXX:5060>
Call-ID: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Date: Sat, 12 Aug 2017 09:15:05 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 444
v=0
o=root 464103664 464103664 IN IP4 XXX.XXX.XXX.XXX
s=Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
c=IN IP4 XXX.XXX.XXX.XXX
b=CT:384
t=0 0
m=audio 17254 RTP/AVP 110 97 9 18 101
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=0
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:30
a=sendrecv
m=video 11024 RTP/AVP 99
a=rtpmap:99 H264/90000
a=sendrecv
---
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #989
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for XXX.XXX.XXX.YYY:57737
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:57737 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;rport=5060;received=XXX.XXX.XXX.XXX;branch=z9hG4bK1525636e
i: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
f: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
t: <sip:PEERA@XXX.XXX.XXX.YYY;ob>
CSeq: 102 INVITE
l: 0
<------------->
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 1 [ 86]: v: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;rport=5060;received=XXX.XXX.XXX.XXX;branch=z9hG4bK1525636e
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 2 [ 52]: i: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 3 [ 45]: f: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 4 [ 36]: t: <sip:PEERA@XXX.XXX.XXX.YYY;ob>
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 6 [ 4]: l: 0
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c: --- (7 headers 0 lines) ---
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: = Looking for Call ID: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060 (Checking To) --From tag as2afc4f25 --To-tag
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: *** SIP TIMER: Cancelling retransmission #989 - INVITE (got response)
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060' Request 102: Found
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: SIP response 100 to standard invite
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:52589 --->
<------------->
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:57737 --->
SIP/2.0 486 Busy Here
v: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;rport=5060;received=XXX.XXX.XXX.XXX;branch=z9hG4bK1525636e
i: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
f: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
t: <sip:PEERA@XXX.XXX.XXX.YYY;ob>;tag=56760812-6714-4a46-a65d-cdccdd2ea607
CSeq: 102 INVITE
l: 0
<------------->
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 0 [ 21]: SIP/2.0 486 Busy Here
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 1 [ 86]: v: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;rport=5060;received=XXX.XXX.XXX.XXX;branch=z9hG4bK1525636e
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 2 [ 52]: i: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 3 [ 45]: f: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 4 [ 77]: t: <sip:PEERA@XXX.XXX.XXX.YYY;ob>;tag=56760812-6714-4a46-a65d-cdccdd2ea607
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: Header 6 [ 4]: l: 0
[2017-08-12 11:15:05] VERBOSE[15018] chan_sip.c: --- (7 headers 0 lines) ---
[2017-08-12 11:15:05] DEBUG[15018] chan_sip.c: = Looking for Call ID: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060 (Checking To) --From tag as2afc4f25 --To-tag 56760812-6714-4a46-a65d-cdccdd2ea607
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Acked pending invite 102
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Stopping retransmission on '447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060' of Request 102: Match Found
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c007128'
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:05] VERBOSE[15018][C-0000004a] chan_sip.c: Transmitting (NAT) to XXX.XXX.XXX.YYY:57737:
ACK sip:PEERA@XXX.XXX.XXX.YYY:57737;ob SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK1525636e;rport
Max-Forwards: 70
From: <sip:PEERC@XXX.XXX.XXX.XXX>;tag=as2afc4f25
To: <sip:PEERA@XXX.XXX.XXX.YYY:57737;ob>;tag=56760812-6714-4a46-a65d-cdccdd2ea607
Contact: <sip:PEERC@XXX.XXX.XXX.XXX:5060>
Call-ID: 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Content-Length: 0
---
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Trying to put 'ACK sip:EMQ' onto UDP socket destined for XXX.XXX.XXX.YYY:57737
[2017-08-12 11:15:05] DEBUG[15018][C-0000004a] chan_sip.c: Setting SIP_ALREADYGONE on dialog 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[14988] cdr.c: Finalized CDR for SIP/PEERC-0000002f - start 1502529305.118131 answer 0.000000 end 1502529305.347494 dispo BUSY
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] channel.c: Hanging up channel 'SIP/PEERA-00000030'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Hangup call SIP/PEERA-00000030, SIP callid 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: update_call_counter(PEERA) - decrement call limit counter on hangup
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Updating call counter for outgoing call
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] chan_sip.c: Call to peer 'PEERA' removed from call limit 2147483647
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERA
[2017-08-12 11:15:05] DEBUG[14986] chan_sip.c: Checking device state for peer PEERA
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: Changing state for SIP/PEERA - state 2 (In use)
[2017-08-12 11:15:05] DEBUG[15052] app_queue.c: Device 'SIP/PEERA' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c007128'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:05] DEBUG[14988] cdr.c: Finalized CDR for SIP/PEERA-00000030 - start 1502529305.123400 answer 0.000000 end 1502529305.347814 dispo BUSY
[2017-08-12 11:15:05] DEBUG[14988] cdr.c: CDR for SIP/PEERA-00000030 is dialed and has no Party B; discarding
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERA
[2017-08-12 11:15:05] DEBUG[14986] chan_sip.c: Checking device state for peer PEERA
[2017-08-12 11:15:05] DEBUG[14986] devicestate.c: Changing state for SIP/PEERA - state 2 (In use)
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] app_dial.c: Exiting with DIALSTATUS=BUSY.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '2' AND context = 'sip-ctx'
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:05] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '2' AND context = 'sip-ctx'
[2017-08-12 11:15:06] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:53785 --->
<------------->
[2017-08-12 11:15:06] DEBUG[15018] chan_sip.c: Destroying SIP dialog 447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060
[2017-08-12 11:15:06] VERBOSE[15018] chan_sip.c: Really destroying SIP dialog '447baf426d6542bb29c5e0ea72ae4879@XXX.XXX.XXX.XXX:5060' Method: INVITE
[2017-08-12 11:15:06] DEBUG[15018] rtp_engine.c: Destroyed RTP instance '0x7fde8c007128'
[2017-08-12 11:15:06] DEBUG[15018] rtp_engine.c: Destroyed RTP instance '0x7fde8c01fdc8'
[2017-08-12 11:15:06] DEBUG[15018] chan_sip.c: SIP TIMER: Rescheduling retransmission #975 (7) BYE - 8
[2017-08-12 11:15:06] DEBUG[15018] chan_sip.c: ** SIP timers: Rescheduling retransmission 8 to 4000 ms (t1 500 ms (Retrans id #975))
[2017-08-12 11:15:06] VERBOSE[15018] chan_sip.c: Retransmitting #7 (NAT) to XXX.XXX.XXX.YYY:55787:
BYE sip:PEERC@XXX.XXX.XXX.YYY:55787;ob SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK7be31efa;rport
Max-Forwards: 70
From: sip:ZKT532WZT@XXX.XXX.XXX.XXX;tag=as0fdc5ae6
To: sip:PEERC@XXX.XXX.XXX.XXX;tag=854a0e90-9543-4e55-a6fb-b79a27ff42bc
Call-ID: 1df2a47b-4b4d-456d-b647-69ce981cb816
CSeq: 102 BYE
User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Proxy-Authorization: Digest username="PEERC", realm="asterisk", algorithm=MD5, uri="sip:XXX.XXX.XXX.XXX", nonce="7d6618c2", response="97739f2cf73b9705563674199fd7154e"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0
---
[2017-08-12 11:15:06] DEBUG[15018] chan_sip.c: Trying to put 'BYE sip:PKN' onto UDP socket destined for XXX.XXX.XXX.YYY:55787
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '3' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '3' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Expression result is '0'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Not taking any branch
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '4' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '4' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Expression result is '0'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] pbx.c: Not taking any branch
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '5' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'exec845' AND priority = '5' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
Log part 3
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '2' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '2' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'PEERA' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:06] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '_%' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:08] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:57737 --->
<------------->
[2017-08-12 11:15:08] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:87.64.21.27:50759 --->
<------------->
[2017-08-12 11:15:10] DEBUG[15018] chan_sip.c: SIP TIMER: Rescheduling retransmission #975 (8) BYE - 8
[2017-08-12 11:15:10] DEBUG[15018] chan_sip.c: ** SIP timers: Rescheduling retransmission 9 to 4000 ms (t1 500 ms (Retrans id #975))
[2017-08-12 11:15:10] VERBOSE[15018] chan_sip.c: Retransmitting #8 (NAT) to XXX.XXX.XXX.YYY:55787:
BYE sip:PEERC@XXX.XXX.XXX.YYY:55787;ob SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK7be31efa;rport
Max-Forwards: 70
From: sip:ZKT532WZT@XXX.XXX.XXX.XXX;tag=as0fdc5ae6
To: sip:PEERC@XXX.XXX.XXX.XXX;tag=854a0e90-9543-4e55-a6fb-b79a27ff42bc
Call-ID: 1df2a47b-4b4d-456d-b647-69ce981cb816
CSeq: 102 BYE
User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Proxy-Authorization: Digest username="PEERC", realm="asterisk", algorithm=MD5, uri="sip:XXX.XXX.XXX.XXX", nonce="7d6618c2", response="97739f2cf73b9705563674199fd7154e"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0
---
[2017-08-12 11:15:10] DEBUG[15018] chan_sip.c: Trying to put 'BYE sip:PKN' onto UDP socket destined for XXX.XXX.XXX.YYY:55787
[2017-08-12 11:15:10] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:185.81.141.110:37425 --->
<------------->
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP opening session. Top level
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP Request URI is /asterisk/rawman?action=login&username=admin&secret=fxt39amb
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [httpstatus] len 10
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [phoneprov] len 9
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [amanager] len 8
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [backups] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [arawman] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [manager] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [rawman] len 6
[2017-08-12 11:15:10] DEBUG[15640] http.c: Match made with [rawman]
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header action: login
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header username: admin
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header secret: fxt39amb
[2017-08-12 11:15:10] DEBUG[15640] manager.c: Running action 'Login'
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP keeping session open. status_code:200
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP Request URI is /asterisk/rawman?action=getvar&actionid=123456&variable=DEVICE_STATE(SIP/PEERA)
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [httpstatus] len 10
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [phoneprov] len 9
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [amanager] len 8
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [backups] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [arawman] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [manager] len 7
[2017-08-12 11:15:10] DEBUG[15640] http.c: match request [rawman] with handler [rawman] len 6
[2017-08-12 11:15:10] DEBUG[15640] http.c: Match made with [rawman]
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP Cookie, Name: '$Version' Value: '1'
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP Cookie, Name: 'mansession_id' Value: 'b50c3065'
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header action: getvar
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header actionid: 123456
[2017-08-12 11:15:10] DEBUG[15640] manager.c: HTTP Manager add header variable: DEVICE_STATE(SIP/PEERA)
[2017-08-12 11:15:10] DEBUG[15640] manager.c: Running action 'Getvar'
[2017-08-12 11:15:10] DEBUG[15640] http.c: HTTP keeping session open. status_code:200
[2017-08-12 11:15:11] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:178.135.38.68:10787 --->
<------------->
[2017-08-12 11:15:13] DEBUG[15629] threadpool.c: Worker thread idle timeout reached. Dying.
[2017-08-12 11:15:13] DEBUG[14974] threadpool.c: Destroying worker thread 108
[2017-08-12 11:15:13] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:60339 --->
<------------->
[2017-08-12 11:15:14] DEBUG[15018] chan_sip.c: SIP TIMER: Rescheduling retransmission #975 (9) BYE - 8
[2017-08-12 11:15:14] DEBUG[15018] chan_sip.c: ** SIP timers: Rescheduling retransmission 10 to 4000 ms (t1 500 ms (Retrans id #975))
[2017-08-12 11:15:14] VERBOSE[15018] chan_sip.c: Retransmitting #9 (NAT) to XXX.XXX.XXX.YYY:55787:
BYE sip:PEERC@XXX.XXX.XXX.YYY:55787;ob SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK7be31efa;rport
Max-Forwards: 70
From: sip:ZKT532WZT@XXX.XXX.XXX.XXX;tag=as0fdc5ae6
To: sip:PEERC@XXX.XXX.XXX.XXX;tag=854a0e90-9543-4e55-a6fb-b79a27ff42bc
Call-ID: 1df2a47b-4b4d-456d-b647-69ce981cb816
CSeq: 102 BYE
User-Agent: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Proxy-Authorization: Digest username="PEERC", realm="asterisk", algorithm=MD5, uri="sip:XXX.XXX.XXX.XXX", nonce="7d6618c2", response="97739f2cf73b9705563674199fd7154e"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0
---
[2017-08-12 11:15:14] DEBUG[15018] chan_sip.c: Trying to put 'BYE sip:PKN' onto UDP socket destined for XXX.XXX.XXX.YYY:55787
[2017-08-12 11:15:15] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:61986 --->
<------------->
[2017-08-12 11:15:16] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:59320 --->
<------------->
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 't' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'e' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:16] WARNING[15632][C-0000004a] pbx.c: Timeout, but no rule 't' or 'e' in context 'sip-ctx'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] channel.c: Soft-Hanging (0x10) up channel 'SIP/PEERC-0000002f'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND priority = '1' AND context = 'sip-ctx'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] channel.c: Hanging up channel 'SIP/PEERC-0000002f'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: Hangup call SIP/PEERC-0000002f, SIP callid 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: update_call_counter(PEERC) - decrement call limit counter on hangup
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: Updating call counter for incoming call
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: Call from peer 'PEERC' removed from call limit 2147483647
[2017-08-12 11:15:16] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERC
[2017-08-12 11:15:16] DEBUG[14986] chan_sip.c: Checking device state for peer PEERC
[2017-08-12 11:15:16] DEBUG[14986] devicestate.c: Changing state for SIP/PEERC - state 1 (Not in use)
[2017-08-12 11:15:16] DEBUG[15052] app_queue.c: Device 'SIP/PEERC' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: Hanging up channel in state Ring (not UP)
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c099988'
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fde8c002ba8'
[2017-08-12 11:15:16] VERBOSE[15632][C-0000004a] chan_sip.c: Scheduling destruction of SIP dialog '64b5f9a6-0b7e-4a38-a37d-747005234d5b' in 32000 ms (Method: INVITE)
[2017-08-12 11:15:16] VERBOSE[15632][C-0000004a] chan_sip.c:
<--- Reliably Transmitting (NAT) to XXX.XXX.XXX.YYY:52589 --->
SIP/2.0 486 Busy here
Via: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0;received=XXX.XXX.XXX.YYY;rport=52589
From: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
To: sip:PEERA@XXX.XXX.XXX.XXX;tag=as69b3816c
Call-ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26213 INVITE
Server: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
<------------>
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #992
[2017-08-12 11:15:16] DEBUG[15632][C-0000004a] chan_sip.c: Trying to put 'SIP/2.0 486' onto UDP socket destined for XXX.XXX.XXX.YYY:52589
[2017-08-12 11:15:16] DEBUG[14988] cdr.c: Finalized CDR for SIP/PEERC-0000002f - start 1502529305.349236 answer 0.000000 end 1502529316.375478 dispo BUSY
[2017-08-12 11:15:16] DEBUG[14988] cdr_radius.c: Unable to create RADIUS record. CDR not recorded!
[2017-08-12 11:15:16] DEBUG[14988] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"" <PEERC>','PEERC','PEERA','sip-ctx','SIP/PEERC-0000002f','SIP/PEERA-00000030','Dial','SIP/PEERA','2017-08-12 11:15:05','2017-08-12 11:15:05','0','0','BUSY','DOCUMENTATION','1502529305.84')
[2017-08-12 11:15:16] DEBUG[14986] devicestate.c: No provider found, checking channel drivers for SIP - PEERC
[2017-08-12 11:15:16] DEBUG[14986] chan_sip.c: Checking device state for peer PEERC
[2017-08-12 11:15:16] DEBUG[14986] devicestate.c: Changing state for SIP/PEERC - state 1 (Not in use)
[2017-08-12 11:15:16] DEBUG[14988] cdr.c: Skipping CDR for SIP/PEERC-0000002f since we weren't answered
[2017-08-12 11:15:16] DEBUG[15018] chan_sip.c: SIP TIMER: Rescheduling retransmission #992 (1) SIP/2.0 - 1
[2017-08-12 11:15:16] DEBUG[15018] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #992))
[2017-08-12 11:15:16] VERBOSE[15018] chan_sip.c: Retransmitting #1 (NAT) to XXX.XXX.XXX.YYY:52589:
SIP/2.0 486 Busy here
Via: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0;received=XXX.XXX.XXX.YYY;rport=52589
From: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
To: sip:PEERA@XXX.XXX.XXX.XXX;tag=as69b3816c
Call-ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26213 INVITE
Server: Asterisk PBX 13.1.0~dfsg-1.1ubuntu4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0
---
[2017-08-12 11:15:16] DEBUG[15018] chan_sip.c: Trying to put 'SIP/2.0 486' onto UDP socket destined for XXX.XXX.XXX.YYY:52589
[2017-08-12 11:15:17] VERBOSE[15018] chan_sip.c:
<--- SIP read from UDP:XXX.XXX.XXX.YYY:52589 --->
ACK sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0
Max-Forwards: 70
f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
t: sip:PEERA@XXX.XXX.XXX.XXX;tag=as69b3816c
i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
CSeq: 26213 ACK
l: 0
<------------->
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 0 [ 56]: ACK sip:PEERA@XXX.XXX.XXX.XXX:5060;transport=UDP SIP/2.0
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 1 [ 94]: v: SIP/2.0/UDP XXX.XXX.XXX.YYY:52589;rport;branch=z9hG4bKPjebe22132-52e8-4140-8364-a4fcaa8015f0
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 3 [ 69]: f: sip:PEERC@XXX.XXX.XXX.XXX;tag=e0372590-c4bb-4909-a156-0f83642b5f78
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 4 [ 43]: t: sip:PEERA@XXX.XXX.XXX.XXX;tag=as69b3816c
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 5 [ 39]: i: 64b5f9a6-0b7e-4a38-a37d-747005234d5b
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 6 [ 15]: CSeq: 26213 ACK
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: Header 7 [ 4]: l: 0
[2017-08-12 11:15:17] VERBOSE[15018] chan_sip.c: --- (8 headers 0 lines) ---
[2017-08-12 11:15:17] DEBUG[15018] chan_sip.c: = Looking for Call ID: 64b5f9a6-0b7e-4a38-a37d-747005234d5b (Checking From) --From tag e0372590-c4bb-4909-a156-0f83642b5f78 --To-tag as69b3816c
[2017-08-12 11:15:17] DEBUG[15018][C-0000004a] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2017-08-12 11:15:17] DEBUG[15018][C-0000004a] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #992
[2017-08-12 11:15:17] DEBUG[15018][C-0000004a] chan_sip.c: Stopping retransmission on '64b5f9a6-0b7e-4a38-a37d-747005234d5b' of Response 26213: Match Found
My understanding is that Linphone server maintains an open session with peers while Asterisk needs (as a client) to lookup and connect to peers when necessary. Is this correct? Isn’t it possible for Asterisk to become a pure server just like Linphone? Why?
Thank you very much for your help.
Whether a connection is held depends on whether UDP or TCP is used. You need to read a primer on SIP to understand UACs and UASes. However, it no longer looks like a DNS issue.
Whilst you don’t seem to have set verbosity to 5, so I can’t see what applications you are executing It would also help if you reproduced this without using Asterisk Realtime, as that is just complicating the logs, and will make it difficult for you to provide your dialplan on the forum.
It looks as though you have executed dialplan code that expects to receive a new number. autofallthrough=no might do that, although that is not an option I’ve ever seen anyone use. On the other hand, I would expect that to log something, even at your verbosity level.
There is an outgoing BYE that I’m assuming is unrelated. The peer is failing to respond to that BYE.
Thank you very much for your support.
I tried with TCP and the results were the same duration wise. Sorry for the log. I will try to provide one with verbosity 5 asap.
As to dialplan code, the only application used is Dial:
Each extension calls this routine : Gosub | routine,1(${EXTEN})
1 | Dial | SIP/${ARG1} |
2 | Wait | 1 |
3 | GotoIf | $["${DIALSTATUS}" = “CHANUNAVAIL”]?1 |
4 | GotoIf | $["${DIALSTATUS}" = “CONGESTION”]?1 |
5 | Return | |
Update: Even when using UDP transport, response is still very quick using Linphone.
As I said, the logs, even though not sufficiently complete, indicate that problem is in the dialplan not the SIP handling, so TCP v UDP is a red herring. It would have been, even for a DNS problem, as the solution for a DNS problem is to fix the DNS configuration. Asterisk will do DNS lookups if it might need them, not at the last moment, when it definitely needs them.
Your real problem is either n the general section of extensions.conf, or in the specific dialplan that follows the call to Dial.