Callee codec rejected

Hello,

We have two sip phones A and B.

A offers G729 and G722 respectively.

B offers only G722.

Codecs listed in sip.conf are G729 and G722 respectively. .

When A calls B we expect G722 to be selected but the call is ending immediately when B answers. It seems like Asterisk is requiring that B uses G729 which B hasn’t. Console output:

[2017-10-26 13:07:45] WARNING[26933][C-00000009]: channel.c:5493 set_format: Unable to find a codec translation path: (slin) -> (g729)
[2017-10-26 13:07:45] WARNING[26933][C-00000009]: indications.c:140 playtones_alloc: Unable to set 'SIP/peera-00000005' to signed linear format (write)
[2017-10-26 13:07:45] WARNING[26933][C-00000009]: channel.c:4559 indicate_data_internal: Unable to handle indication 3 for 'SIP/peera-00000005'
[2017-10-26 13:07:47] WARNING[26821][C-00000009]: channel.c:5493 set_format: Unable to find a codec translation path: (g722) -> (g729)
[2017-10-26 13:07:47] WARNING[26821][C-00000009]: channel.c:5493 set_format: Unable to find a codec translation path: (g729) -> (g722)
    -- SIP/peerb-00000006 answered SIP/peera-00000005
[2017-10-26 13:07:47] WARNING[26933][C-00000009]: channel.c:6456 ast_channel_make_compatible_helper: No path to translate from SIP/peerb-00000006 to SIP/peera-00000005
[2017-10-26 13:07:47] WARNING[26933][C-00000009]: app_dial.c:3176 dial_exec_full: Had to drop call because I couldn't make SIP/peera-00000005 compatible with SIP/peerb-00000006
  == Spawn extension (from-sip, chexec, 2) exited non-zero on 'SIP/peera-00000005'

How could we get Asterisk to allow such a call using G722 which all parties actually have?

Thanks

Don’t offer to accept g729.

Note that you are not ending up with both codecs on the A side suggest you either don’t have both configured, or the phone doesn’t, or the phone is somehow restricting you to just G.729.

Assuming early offer, which should happen is phone offers both, Asterisk offers both, Asterisk selects both with the first one preferred. It then makes an offer to B, with the best choice from A, but presumably for both. B responds with just g722. B is allowed to send either g729 or g722, even though it didn’t offer g.729, and probably can’t use it.

If A only offered g729, Asterisk will actually respond with just g729, even though SIP doesn’t require that. In that case, it is trivially obvious that the call cannot precede without a codec module. If Asterisk is only configured with g729, for that peer, it will not try to forward g722 to it, even if the peer offers it, even though that would be allowed by SIP.

A could do a late offer, in which case, Asterisk should respond with both, and A might decide to only offer its preferred option which, if g729, would cause your problem.

I think we really need to see the full sip debug, with both debug and verbose logs, to see what was actually negotiated.

In particular, Asterisk does not feed back codec information for the B side to the A side. There is nothing in its internal signalling that can do that.

(Whilst I say negotiated, the SIP standard actually doesn’t negotiate codecs, it simply informs the other side which ones are acceptable for media going towards the sender of the SDP.)

1 Like

Here’s the log :

<--- SIP read from UDP:XX.XX.XX.XX:49916 --->
INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:49916;rport;branch=z9hG4bKPjd171f53d-e65c-4cc5-ba71-774919e806c6
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
t: sip:peerb@XX.XX.XX.ZZ
m: <sip:peera@XX.XX.XX.XX:49916;ob>
i: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32214 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Android test agent
c: application/sdp
l: 483

v=0
o=- 3717997136 3717997136 IN IP4 XX.XX.XX.YY
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 51992 RTP/AVP 99 98 9 104 97 3 18 8 0 96
c=IN IP4 XX.XX.XX.YY
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:1a3ce6f0
a=ice-pwd:120d7749
a=candidate:Hac100e1a 1 UDP 2130706431 XX.XX.XX.YY 51992 typ host
<------------->
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: --- (14 headers 22 lines) ---
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Sending to XX.XX.XX.XX:49916 (NAT)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Sending to XX.XX.XX.XX:49916 (NAT)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Using INVITE request as basis request - 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Scheduling destruction of SIP dialog '5f67b73d7e1b1beb04bef0162e7a8421@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:49916:
NOTIFY sip:peera@XX.XX.XX.XX:49916;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK6b11621d;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as4ff06749
To: <sip:peera@XX.XX.XX.XX:49916;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 5f67b73d7e1b1beb04bef0162e7a8421@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found peer 'peera' for 'peera' from XX.XX.XX.XX:49916
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: 
<--- Reliably Transmitting (NAT) to XX.XX.XX.XX:49916 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XX.XX:49916;branch=z9hG4bKPjd171f53d-e65c-4cc5-ba71-774919e806c6;received=XX.XX.XX.XX;rport=49916
From: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
To: sip:peerb@XX.XX.XX.ZZ;tag=as5a1fbf2f
Call-ID: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32214 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="609fabf2"
Content-Length: 0

<------------>
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Scheduling destruction of SIP dialog '2589098962' in 32000 ms (Method: REGISTER)
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:49916 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK6b11621d
i: 5f67b73d7e1b1beb04bef0162e7a8421@XX.XX.XX.ZZ:5060
f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as4ff06749
t: <sip:peera@XX.XX.XX.XX;ob>;tag=z9hG4bK6b11621d
CSeq: 102 NOTIFY
l: 0

<------------->
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Really destroying SIP dialog '5f67b73d7e1b1beb04bef0162e7a8421@XX.XX.XX.ZZ:5060' Method: NOTIFY
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Really destroying SIP dialog '4288952797' Method: REGISTER
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:49916 --->
ACK sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:49916;rport;branch=z9hG4bKPjd171f53d-e65c-4cc5-ba71-774919e806c6
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
t: sip:peerb@XX.XX.XX.ZZ;tag=as5a1fbf2f
i: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32214 ACK
l: 0

<--- SIP read from UDP:XX.XX.XX.XX:49916 --->
INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:49916;rport;branch=z9hG4bKPj71118c9d-ccaf-4cc0-9f65-71edb968f37a
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
t: sip:peerb@XX.XX.XX.ZZ
m: <sip:peera@XX.XX.XX.XX:49916;ob>
i: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32215 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Android test agent
Authorization: Digest username="peera", realm="asterisk", nonce="609fabf2", uri="sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP", response="45409a7c95274dcb6bf6c38c7b8edadf", algorithm=MD5
c: application/sdp
l: 483

v=0
o=- 3717997136 3717997136 IN IP4 XX.XX.XX.YY
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 51992 RTP/AVP 99 98 9 104 97 3 18 8 0 96
c=IN IP4 XX.XX.XX.YY
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:1a3ce6f0
a=ice-pwd:120d7749
a=candidate:Hac100e1a 1 UDP 2130706431 XX.XX.XX.YY 51992 typ host
<------------->
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: --- (15 headers 22 lines) ---
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Sending to XX.XX.XX.XX:49916 (NAT)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Using INVITE request as basis request - 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Scheduling destruction of SIP dialog '7d01b75c5315790e7db9c96b06bb3781@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:49916:
NOTIFY sip:peera@XX.XX.XX.XX:49916;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK2c730f0a;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as690b3813
To: <sip:peera@XX.XX.XX.XX:49916;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 7d01b75c5315790e7db9c96b06bb3781@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found peer 'peera' for 'peera' from XX.XX.XX.XX:49916
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] netsock2.c: Using SIP VIDEO CoS mark 6
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] netsock2.c: Using SIP RTP CoS mark 5
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 99
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 98
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 9
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 104
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 97
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 3
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 18
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 8
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 0
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 96
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format speex for ID 99
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format speex for ID 98
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format iLBC for ID 104
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format speex for ID 97
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format telephone-event for ID 96
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Capabilities: us - (g729|g722|h264), peer - audio=(ulaw|gsm|alaw|g722|g729|speex|speex16|speex32|mpeg4)/video=(nothing)/text=(nothing), combined - (g729|g722)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Peer audio RTP is at port XX.XX.XX.YY:51992
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Peer doesn't provide video
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: Looking for peerb in sip-ctx (domain XX.XX.XX.ZZ)
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] sip/route.c: sip_route_dump: route/path hop: <sip:peera@XX.XX.XX.XX:49916;ob>
[2017-10-26 10:58:57] VERBOSE[15021][C-0000147b] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:49916 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP XX.XX.XX.XX:49916;branch=z9hG4bKPj71118c9d-ccaf-4cc0-9f65-71edb968f37a;received=XX.XX.XX.XX;rport=49916
From: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
To: sip:peerb@XX.XX.XX.ZZ
Call-ID: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32215 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:peerb@XX.XX.XX.ZZ:5060>
Content-Length: 0

<------------>
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Scheduling destruction of SIP dialog '2522834241' in 32000 ms (Method: REGISTER)
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: Really destroying SIP dialog '915265970' Method: REGISTER
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] pbx_realtime.c: Executing [dpp@sip-ctx:2] Dial("SIP/peera-0000055c", "SIP/peerb")
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] netsock2.c: Using SIP VIDEO CoS mark 6
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] netsock2.c: Using SIP RTP CoS mark 5
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: Audio is at 19580
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: Adding codec g729 to SDP
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: Adding codec g722 to SDP
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:56552:
INVITE sip:peerb@XX.XX.XX.XX:56552;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK0bd4e2c5;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
To: <sip:peerb@XX.XX.XX.XX:56552;ob>
Contact: <sip:peera@XX.XX.XX.ZZ:5060>
Call-ID: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX GIT-master-b3914dfM
Date: Thu, 26 Oct 2017 08:58:57 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 297

v=0
o=root 1677906749 1677906749 IN IP4 XX.XX.XX.ZZ
s=Asterisk PBX GIT-master-b3914dfM
c=IN IP4 XX.XX.XX.ZZ
t=0 0
m=audio 19580 RTP/AVP 18 9 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] app_dial.c: Called SIP/peerb

<--- SIP read from UDP:XX.XX.XX.XX:56552 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK0bd4e2c5
i: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
t: <sip:peerb@XX.XX.XX.XX;ob>
CSeq: 102 INVITE
l: 0

<------------->
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-26 10:58:57] VERBOSE[15021] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:56552 --->
SIP/2.0 180 Ringing
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK0bd4e2c5
i: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=3b06d9dd-e757-450f-ab76-dec3ced511ef
CSeq: 102 INVITE
m: <sip:peerb@XX.XX.XX.XX:56552;ob>
l: 0

<------------->
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] app_dial.c: SIP/peerb-0000055d is ringing
[2017-10-26 10:58:57] VERBOSE[25858][C-0000147b] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:49916 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP XX.XX.XX.XX:49916;branch=z9hG4bKPj71118c9d-ccaf-4cc0-9f65-71edb968f37a;received=XX.XX.XX.XX;rport=49916
From: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
To: sip:peerb@XX.XX.XX.ZZ;tag=as7b865ded
Call-ID: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32215 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:peerb@XX.XX.XX.ZZ:5060>
Content-Length: 0


<------------>
[2017-10-26 10:58:57] WARNING[25858][C-0000147b] channel.c: Unable to find a codec translation path: (slin) -> (g729)
[2017-10-26 10:58:57] WARNING[25858][C-0000147b] indications.c: Unable to set 'SIP/peera-0000055c' to signed linear format (write)
[2017-10-26 10:58:57] WARNING[25858][C-0000147b] channel.c: Unable to handle indication 3 for 'SIP/peera-0000055c'

[2017-10-26 10:59:01] VERBOSE[15021] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:56552 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK0bd4e2c5
i: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=3b06d9dd-e757-450f-ab76-dec3ced511ef
CSeq: 102 INVITE
m: <sip:peerb@XX.XX.XX.XX:56552;ob>
k: replaces, 100rel, timer, norefersub
c: application/sdp
l: 220

v=0
o=- 3717997140 3717997141 IN IP4 172.16.14.30
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 57959 RTP/AVP 9 101
c=IN IP4 172.16.14.30
b=TIAS:64000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
<------------->
[2017-10-26 10:59:01] VERBOSE[15021] chan_sip.c: --- (10 headers 12 lines) ---
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 9
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Found RTP audio format 101
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Found audio description format telephone-event for ID 101
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Capabilities: us - (g729|g722|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722)
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Peer audio RTP is at port 172.16.14.30:57959
[2017-10-26 10:59:01] WARNING[15021][C-0000147b] channel.c: Unable to find a codec translation path: (g722) -> (g729)
[2017-10-26 10:59:01] WARNING[15021][C-0000147b] channel.c: Unable to find a codec translation path: (g729) -> (g722)
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] sip/route.c: sip_route_dump: route/path hop: <sip:peerb@XX.XX.XX.XX:56552;ob>
[2017-10-26 10:59:01] VERBOSE[15021][C-0000147b] chan_sip.c: Transmitting (NAT) to XX.XX.XX.XX:56552:
ACK sip:peerb@XX.XX.XX.XX:56552;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK43131707;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
To: <sip:peerb@XX.XX.XX.XX:56552;ob>;tag=3b06d9dd-e757-450f-ab76-dec3ced511ef
Contact: <sip:peera@XX.XX.XX.ZZ:5060>
Call-ID: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX GIT-master-b3914dfM
Content-Length: 0


<------------->
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] app_dial.c: SIP/peerb-0000055d answered SIP/peera-0000055c
[2017-10-26 10:59:01] VERBOSE[15021] chan_sip.c: --- (11 headers 0 lines) ---
[2017-10-26 10:59:01] WARNING[25858][C-0000147b] channel.c: No path to translate from SIP/peerb-0000055d to SIP/peera-0000055c
[2017-10-26 10:59:01] WARNING[25858][C-0000147b] app_dial.c: Had to drop call because I couldn't make SIP/peera-0000055c compatible with SIP/peerb-0000055d
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] chan_sip.c: Scheduling destruction of SIP dialog '28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060' in 32000 ms (Method: INVITE)
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:56552:
BYE sip:peerb@XX.XX.XX.XX:56552;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK67d187cf;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
To: <sip:peerb@XX.XX.XX.XX:56552;ob>;tag=3b06d9dd-e757-450f-ab76-dec3ced511ef
Call-ID: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
CSeq: 103 BYE
User-Agent: Asterisk PBX GIT-master-b3914dfM
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] pbx.c: Spawn extension (sip-ctx, chexec, 2) exited non-zero on 'SIP/peera-0000055c'


<------------>
[2017-10-26 10:59:01] VERBOSE[15021] chan_sip.c: Scheduling destruction of SIP dialog '3781171210' in 32000 ms (Method: REGISTER)
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] chan_sip.c: Scheduling destruction of SIP dialog '369a21ac-bd49-41fd-9360-3b0e7afdc5c8' in 32000 ms (Method: INVITE)
[2017-10-26 10:59:01] VERBOSE[25858][C-0000147b] chan_sip.c: 
<--- Reliably Transmitting (NAT) to XX.XX.XX.XX:49916 --->
SIP/2.0 603 Declined
Via: SIP/2.0/UDP XX.XX.XX.XX:49916;branch=z9hG4bKPj71118c9d-ccaf-4cc0-9f65-71edb968f37a;received=XX.XX.XX.XX;rport=49916
From: sip:peera@XX.XX.XX.ZZ;tag=fce3ed6b-fd55-4508-a63c-00acdf6a3756
To: sip:peerb@XX.XX.XX.ZZ;tag=as7b865ded
Call-ID: 369a21ac-bd49-41fd-9360-3b0e7afdc5c8
CSeq: 32215 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0

<--- SIP read from UDP:XX.XX.XX.XX:56552 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK67d187cf
i: 28c5276e337ada7357d7c08d15486d25@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as793cc152
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=3b06d9dd-e757-450f-ab76-dec3ced511ef
CSeq: 103 BYE
l: 0

In sip.conf we have all disallowed, then allow g729 before g722

Thank you for your help!

We must offer it because some phones have it while others don’t.

Only allow it on the phones that support it.


[endpointA]
type=endpoint
disallow=all
allow=g722,g729
transport=transport-udp
context=internal
outbound_auth=endpointA_auth
aors=endpointA

[endpointB]
type=endpoint
disallow=all
allow=g729
transport=transport-udp
context=internal
outbound_auth=endpointB_auth
aors=endpointB

If you offer it to phones that only support it, those phones will not be able to communicate with phones that don’t support it, unless you install (and licence) a g.729 codec.

You didn’t include the debug DEBUG log output, so we cannot see Asterisk’s reasoning on choice of codecs.

Some phones (A) have both g729 and g722 while others (B) only have g722. We are assuming that ideally there should not be a problem since both codecs are also listed in Asterisk’s sip.conf. There is no need in our opinion to specify codecs for each phone individually. Normally, when A phones call each other, g729 should be selected while g722 should be selected in all other cases. How do we get this to work?

g729 has highest priority on A phones, followed by g722. g729 also precedes g722 in sip.conf.

I will provide the DEBUG log asap.

Thanks

We have this in logger.conf :

full => notice,warning,error,debug,verbose,dtmf,fax

Also in CLI :

core set debug 5
core set verbose 5
sip set debug on

What else do we need to enable?

Thanks

You need to enable a log file that covers the debug category. Typically, you do that by un-commenting the full log.

Here’s the log with the debug info. Thanks.

PART 1


 
<------------->
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:55733;rport;branch=z9hG4bKPj2c49664b-d8df-4b7e-96a1-8e2dd95a412c
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  6 [ 19]: CSeq: 4153 REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  8 [ 37]: m: <sip:peerb@XX.XX.XX.XX:55733;ob>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  9 [ 10]: Expires: 0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header 10 [  4]: l: 0
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: --- (11 headers 0 lines) ---
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0 (Checking From) --From tag 9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a --To-tag   
[2017-10-27 08:30:37] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:55733' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '55733'.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:55733 (NAT)
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for 608433b8-8e8b-44fd-bea9-fac403d6c5c0 - REGISTER (No RTP)
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:55733' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '55733'.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:55733 (NAT)
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:55733 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XX.XX:55733;branch=z9hG4bKPj2c49664b-d8df-4b7e-96a1-8e2dd95a412c;received=XX.XX.XX.XX;rport=55733
From: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as627c1e4f
Call-ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
CSeq: 4153 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="152d5018"
Content-Length: 0


<------------>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for XX.XX.XX.XX:55733
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '608433b8-8e8b-44fd-bea9-fac403d6c5c0' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:55733 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:55733;rport;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
t: <sip:peerb@XX.XX.XX.ZZ>
i: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
CSeq: 4154 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XX:55733;ob>
Expires: 0
Authorization: Digest username="peerb", realm="asterisk", nonce="152d5018", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="4421fff520dc9ceb9083fd365aada23c", algorithm=MD5
l: 0

<------------->
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:55733;rport;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  6 [ 19]: CSeq: 4154 REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  8 [ 37]: m: <sip:peerb@XX.XX.XX.XX:55733;ob>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  9 [ 10]: Expires: 0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header 10 [175]: Authorization: Digest username="peerb", realm="asterisk", nonce="152d5018", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="4421fff520dc9ceb9083fd365aada23c", algorithm=MD5
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header 11 [  4]: l: 0
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: --- (12 headers 0 lines) ---
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0 (Checking From) --From tag 9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a --To-tag   
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:55733' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '55733'.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:55733 (NAT)
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Unregistered SIP 'peerb'
[2017-10-27 08:30:37] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:37] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sip_peers SET `fullcontact` = '', `lastms` = '0', `useragent` = '', `regserver` = '', `regseconds` = '0', `port` = '0', `ipaddr` = '' WHERE `name` = 'peerb'
[2017-10-27 08:30:37] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sip_peers
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: -REALTIME- peer expired registration. Name: peerb. Realtime peer objects now 0
[2017-10-27 08:30:37] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:37] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:37] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 5 (Unavailable)
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:55733 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP XX.XX.XX.XX:55733;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719;received=XX.XX.XX.XX;rport=55733
From: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as627c1e4f
Call-ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
CSeq: 4154 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Fri, 27 Oct 2017
Content-Length: 0


<------------>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XX.XX.XX.XX:55733
[2017-10-27 08:30:37] DEBUG[26854] app_queue.c: Device 'SIP/peerb' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '608433b8-8e8b-44fd-bea9-fac403d6c5c0' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:37] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:37] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:37] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 5 (Unavailable)
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:185.81.141.117:48550 --->

<------------->
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:213.204.117.75:56941 --->

<--- SIP read from UDP:XX.XX.XX.XX:55733 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:55733;rport;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
t: <sip:peerb@XX.XX.XX.ZZ>
i: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
CSeq: 4154 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XX:55733;ob>
Expires: 0
Authorization: Digest username="peerb", realm="asterisk", nonce="152d5018", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="4421fff520dc9ceb9083fd365aada23c", algorithm=MD5
l: 0

<------------->
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:55733;rport;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  6 [ 19]: CSeq: 4154 REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  8 [ 37]: m: <sip:peerb@XX.XX.XX.XX:55733;ob>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header  9 [ 10]: Expires: 0
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header 10 [175]: Authorization: Digest username="peerb", realm="asterisk", nonce="152d5018", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="4421fff520dc9ceb9083fd365aada23c", algorithm=MD5
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c:  Header 11 [  4]: l: 0
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: --- (12 headers 0 lines) ---
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0 (Checking From) --From tag 9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a --To-tag   
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 4154, ours 4154)
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 608433b8-8e8b-44fd-bea9-fac403d6c5c0
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:55733' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '55733'.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:55733 (NAT)
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:37] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:55733 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP XX.XX.XX.XX:55733;branch=z9hG4bKPj369788d8-de92-4c76-964f-85838b2b4719;received=XX.XX.XX.XX;rport=55733
From: <sip:peerb@XX.XX.XX.ZZ>;tag=9cdfb1ad-32f8-4077-8d0b-dc5f30960c2a
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as627c1e4f
Call-ID: 608433b8-8e8b-44fd-bea9-fac403d6c5c0
CSeq: 4154 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Fri, 27 Oct 2017
Content-Length: 0

LOG PART 2


<------------>
[2017-10-27 08:30:37] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XX.XX.XX.XX:55733
[2017-10-27 08:30:37] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '608433b8-8e8b-44fd-bea9-fac403d6c5c0' in 32000 ms (Method: REGISTER)

<------------->
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPje02bcde4-c1a3-4942-8a2b-92a08cc9db91
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
t: <sip:peerb@XX.XX.XX.ZZ>
i: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
CSeq: 14237 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XY:50499;ob>;+sip.ice
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 92]: v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPje02bcde4-c1a3-4942-8a2b-92a08cc9db91
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 20]: CSeq: 14237 REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 44]: m: <sip:peerb@XX.XX.XX.XY:50499;ob>;+sip.ice
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 12]: Expires: 900
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 11 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (12 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d (Checking From) --From tag 58966f13-2ddb-49d5-ba66-5047aed3bd8b --To-tag   
[2017-10-27 08:30:39] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XY:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XY' and port '50499'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: NAT detected for XX.XX.XX.XY / XX.XX.XX.XX
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d - REGISTER (No RTP)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XY:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XY' and port '50499'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: NAT detected for XX.XX.XX.XY / XX.XX.XX.XX
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:50499 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XX.XY:50499;branch=z9hG4bKPje02bcde4-c1a3-4942-8a2b-92a08cc9db91;received=XX.XX.XX.XX;rport=50499
From: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as252e42f5
Call-ID: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
CSeq: 14237 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="15bf6a5b"
Content-Length: 0


<------------>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '4f08e136-19bb-4fbe-9b3a-13b5a344ad3d' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPj3ca290de-0c16-46e1-973d-cffc4fee75a0
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
t: <sip:peerb@XX.XX.XX.ZZ>
i: 6e3b8316-743f-4210-aac2-75b15640266c
CSeq: 22561 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XY:50499;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 92]: v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPj3ca290de-0c16-46e1-973d-cffc4fee75a0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 6e3b8316-743f-4210-aac2-75b15640266c
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 20]: CSeq: 22561 REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 35]: m: <sip:peerb@XX.XX.XX.XY:50499;ob>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 12]: Expires: 900
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 11 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (12 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 6e3b8316-743f-4210-aac2-75b15640266c (Checking From) --From tag 858229d3-8492-445a-8d6e-b39ab82a0ebd --To-tag   
[2017-10-27 08:30:39] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XY:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XY' and port '50499'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: NAT detected for XX.XX.XX.XY / XX.XX.XX.XX
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for 6e3b8316-743f-4210-aac2-75b15640266c - REGISTER (No RTP)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 6e3b8316-743f-4210-aac2-75b15640266c
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XY:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XY' and port '50499'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: NAT detected for XX.XX.XX.XY / XX.XX.XX.XX
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:50499 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XX.XY:50499;branch=z9hG4bKPj3ca290de-0c16-46e1-973d-cffc4fee75a0;received=XX.XX.XX.XX;rport=50499
From: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as3f97ed27
Call-ID: 6e3b8316-743f-4210-aac2-75b15640266c
CSeq: 22561 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="00adddf7"
Content-Length: 0


<------------>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '6e3b8316-743f-4210-aac2-75b15640266c' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPj8f0a5f45-096f-4f7a-84c8-b800e35bc745
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
t: <sip:peerb@XX.XX.XX.ZZ>
i: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
CSeq: 14238 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XY:50499;ob>;+sip.ice
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="peerb", realm="asterisk", nonce="15bf6a5b", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="bbe1e58bddae6f5dc2f18448973362fc", algorithm=MD5
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 92]: v: SIP/2.0/UDP XX.XX.XX.XY:50499;rport;branch=z9hG4bKPj8f0a5f45-096f-4f7a-84c8-b800e35bc745
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 20]: CSeq: 14238 REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 44]: m: <sip:peerb@XX.XX.XX.XY:50499;ob>;+sip.ice
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 12]: Expires: 900
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 11 [175]: Authorization: Digest username="peerb", realm="asterisk", nonce="15bf6a5b", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="bbe1e58bddae6f5dc2f18448973362fc", algorithm=MD5
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 12 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (13 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d (Checking From) --From tag 58966f13-2ddb-49d5-ba66-5047aed3bd8b --To-tag   
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XY:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XY' and port '50499'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: NAT detected for XX.XX.XX.XY / XX.XX.XX.XX
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Store REGISTER's src-IP:port for call routing.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: build_path: do not use Path headers
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Registered SIP 'peerb' at XX.XX.XX.XX:50499
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sip_peers SET `ipaddr` = 'XX.XX.XX.XX', `fullcontact` = 'sip:peerb@XX.XX.XX.XY:50499^3Bob', `lastms` = '0', `useragent` = 'Android test agent', `defaultuser` = 'peerb', `regseconds` = '1509086739', `port` = '50499' WHERE `name` = 'peerb'
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sip_peers
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP XX.XX.XX.XY:50499;branch=z9hG4bKPj8f0a5f45-096f-4f7a-84c8-b800e35bc745;received=XX.XX.XX.XX;rport=50499
From: <sip:peerb@XX.XX.XX.ZZ>;tag=58966f13-2ddb-49d5-ba66-5047aed3bd8b
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as252e42f5
Call-ID: 4f08e136-19bb-4fbe-9b3a-13b5a344ad3d
CSeq: 14238 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 900
Contact: <sip:peerb@XX.XX.XX.XY:50499;ob>;expires=900
Date: Fri, 27 Oct 2017
Content-Length: 0


<------------>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for 6660a7a61277551c1195a07f5fa4068a@XX.XX.XX.ZZ:5060 - NOTIFY (No RTP)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-10-27 08:30:39] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: SIP call-id changed from '6660a7a61277551c1195a07f5fa4068a@XX.XX.XX.ZZ:5060' to '6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060'
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method NOTIFY - callid 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 45]: NOTIFY sip:peerb@XX.XX.XX.XY:50499;ob SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 62]: Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK687407f8;rport
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 58]: From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as1f8dfdcf
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 36]: To: <sip:peerb@XX.XX.XX.XY:50499;ob>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 40]: Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 58]: Call-ID: 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 44]: User-Agent: Asterisk PBX GIT-master-b3914dfM
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 22]: Event: message-summary
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 48]: Content-Type: application/simple-message-summary
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:50499:
NOTIFY sip:peerb@XX.XX.XX.XY:50499;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK687407f8;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as1f8dfdcf
To: <sip:peerb@XX.XX.XX.XY:50499;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #1479
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '4f08e136-19bb-4fbe-9b3a-13b5a344ad3d' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:39] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:39] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:39] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 1 (Not in use)
[2017-10-27 08:30:39] DEBUG[26854] app_queue.c: Device 'SIP/peerb' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:50499;rport;branch=z9hG4bKPj9b9e288a-f63f-4b4e-9324-8b08ee5fbd9d
Max-Forwards: 70
f: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
t: <sip:peerb@XX.XX.XX.ZZ>
i: 6e3b8316-743f-4210-aac2-75b15640266c
CSeq: 22562 REGISTER
User-Agent: Android test agent
m: <sip:peerb@XX.XX.XX.XX:50499;ob>
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="peerb", realm="asterisk", nonce="00adddf7", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="0e834cd87b5fe6766d5053583147bec3", algorithm=MD5
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: REGISTER sip:XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:50499;rport;branch=z9hG4bKPj9b9e288a-f63f-4b4e-9324-8b08ee5fbd9d
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 25]: t: <sip:peerb@XX.XX.XX.ZZ>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: 6e3b8316-743f-4210-aac2-75b15640266c
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 20]: CSeq: 22562 REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 37]: m: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 12]: Expires: 900
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 11 [175]: Authorization: Digest username="peerb", realm="asterisk", nonce="00adddf7", uri="sip:XX.XX.XX.ZZ:5060;transport=UDP", response="0e834cd87b5fe6766d5053583147bec3", algorithm=MD5
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 12 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (13 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 6e3b8316-743f-4210-aac2-75b15640266c (Checking From) --From tag 858229d3-8492-445a-8d6e-b39ab82a0ebd --To-tag   
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method REGISTER - callid 6e3b8316-743f-4210-aac2-75b15640266c
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:50499' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '50499'.
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:50499 (NAT)
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:39] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Store REGISTER's src-IP:port for call routing.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: build_path: do not use Path headers
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sip_peers SET `ipaddr` = 'XX.XX.XX.XX', `fullcontact` = 'sip:peerb@XX.XX.XX.XX:50499^3Bob', `lastms` = '0', `useragent` = 'Android test agent', `defaultuser` = 'peerb', `regseconds` = '1509086739', `port` = '50499' WHERE `name` = 'peerb'
[2017-10-27 08:30:39] DEBUG[26821] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sip_peers
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP XX.XX.XX.XX:50499;branch=z9hG4bKPj9b9e288a-f63f-4b4e-9324-8b08ee5fbd9d;received=XX.XX.XX.XX;rport=50499
From: <sip:peerb@XX.XX.XX.ZZ>;tag=858229d3-8492-445a-8d6e-b39ab82a0ebd
To: <sip:peerb@XX.XX.XX.ZZ>;tag=as3f97ed27
Call-ID: 6e3b8316-743f-4210-aac2-75b15640266c
CSeq: 22562 REGISTER
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 900
Contact: <sip:peerb@XX.XX.XX.XX:50499;ob>;expires=900
Date: Fri, 27 Oct 2017
Content-Length: 0


LOG PART 3

<------------>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for 7ebc1ff035fd6d9254f84fb655d7e414@XX.XX.XX.ZZ:5060 - NOTIFY (No RTP)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-10-27 08:30:39] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: SIP call-id changed from '7ebc1ff035fd6d9254f84fb655d7e414@XX.XX.XX.ZZ:5060' to '21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060'
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Initializing initreq for method NOTIFY - callid 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 47]: NOTIFY sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 62]: Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK71f613a6;rport
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 58]: From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as79513224
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 38]: To: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 40]: Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [ 58]: Call-ID: 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  7 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  8 [ 44]: User-Agent: Asterisk PBX GIT-master-b3914dfM
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  9 [ 22]: Event: message-summary
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header 10 [ 48]: Content-Type: application/simple-message-summary
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:50499:
NOTIFY sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK71f613a6;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as79513224
To: <sip:peerb@XX.XX.XX.XX:50499;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #438
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Scheduling destruction of SIP dialog '6e3b8316-743f-4210-aac2-75b15640266c' in 32000 ms (Method: REGISTER)
[2017-10-27 08:30:39] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:39] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:39] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 1 (Not in use)
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK687407f8
i: 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as1f8dfdcf
t: <sip:peerb@XX.XX.XX.XY;ob>;tag=z9hG4bK687407f8
CSeq: 102 NOTIFY
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK687407f8
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 55]: f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as1f8dfdcf
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 49]: t: <sip:peerb@XX.XX.XX.XY;ob>;tag=z9hG4bK687407f8
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060 (Checking To) --From tag as1f8dfdcf --To-tag z9hG4bK687407f8  
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1479
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Stopping retransmission on '6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060' of Request 102: Match Found
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Got 200 accepted on NOTIFY 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Destroying SIP dialog 6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Really destroying SIP dialog '6e2923183885eab3699b114601354d9e@XX.XX.XX.ZZ:5060' Method: NOTIFY
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK71f613a6
i: 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as79513224
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=z9hG4bK71f613a6
CSeq: 102 NOTIFY
l: 0

<------------->
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK71f613a6
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  3 [ 55]: f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as79513224
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  4 [ 51]: t: <sip:peerb@XX.XX.XX.XX;ob>;tag=z9hG4bK71f613a6
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060 (Checking To) --From tag as79513224 --To-tag z9hG4bK71f613a6  
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #438
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Stopping retransmission on '21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060' of Request 102: Match Found
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Got 200 accepted on NOTIFY 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] DEBUG[26821] chan_sip.c: Destroying SIP dialog 21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: Really destroying SIP dialog '21b4a7f121f444a343c179017441549b@XX.XX.XX.ZZ:5060' Method: NOTIFY
[2017-10-27 08:30:39] VERBOSE[26821] chan_sip.c: 


<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj1a5b51f2-125e-45af-a5ff-664c7c5eb837
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
t: sip:peerb@XX.XX.XX.ZZ
m: <sip:peera@XX.XX.XX.XX:51984;ob>
i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21863 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Android test agent
c: application/sdp
l: 346

v=0
o=- 3718074645 3718074645 IN IP4 172.16.14.26
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 37240 RTP/AVP 18 9 96
c=IN IP4 172.16.14.26
b=TIAS:64000
b=RS:0
b=RR:0
a=sendrecv
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ice-ufrag:3a89920f
a=ice-pwd:1c87a1b7
a=candidate:Hac100e1a 1 UDP 2130706431 172.16.14.26 37240 typ host
<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 54]: INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj1a5b51f2-125e-45af-a5ff-664c7c5eb837
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 23]: t: sip:peerb@XX.XX.XX.ZZ
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: m: <sip:peera@XX.XX.XX.XX:51984;ob>
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [ 39]: i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  7 [ 18]: CSeq: 21863 INVITE
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  8 [ 38]: k: replaces, 100rel, timer, norefersub
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  9 [  7]: x: 1800
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 10 [ 10]: Min-SE: 90
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 11 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 12 [ 18]: c: application/sdp
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 13 [  6]: l: 346
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 14 [  0]: 
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  0 [  3]: v=0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  1 [ 45]: o=- 3718074645 3718074645 IN IP4 172.16.14.26
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  2 [  9]: s=pjmedia
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  3 [  7]: b=AS:84
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  4 [  5]: t=0 0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  5 [  9]: a=X-nat:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  6 [ 29]: m=audio 37240 RTP/AVP 18 9 96
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  7 [ 21]: c=IN IP4 172.16.14.26
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  8 [ 12]: b=TIAS:64000
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  9 [  6]: b=RS:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 10 [  6]: b=RR:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 11 [ 10]: a=sendrecv
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 12 [ 32]: a=rtpmap:96 telephone-event/8000
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 13 [ 14]: a=fmtp:96 0-16
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 14 [ 20]: a=ice-ufrag:3a89920f
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 15 [ 18]: a=ice-pwd:1c87a1b7
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 16 [ 66]: a=candidate:Hac100e1a 1 UDP 2130706431 172.16.14.26 37240 typ host
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (14 headers 17 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d (Checking From) --From tag 66803ece-05ba-4f03-8848-79a1fd8eb4bd --To-tag   
[2017-10-27 08:30:46] DEBUG[26821] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.XX:51984' into...
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.XX' and port '51984'.
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: Sending to XX.XX.XX.XX:51984 (NAT)
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Allocating new SIP dialog for ae975bff-38df-408d-9c0a-6acb9bfdce6d - INVITE (No RTP)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub"
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Found SIP option: -replaces-
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Matched SIP option: replaces
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Found SIP option: -100rel-
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Matched SIP option: 100rel
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Found SIP option: -timer-
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Matched SIP option: timer
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Found SIP option: -norefersub-
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] sip/reqresp_parser.c: Matched SIP option: norefersub
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.XX:51984' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.XX' and port '51984'.
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Sending to XX.XX.XX.XX:51984 (NAT)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Initializing initreq for method INVITE - callid ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Using INVITE request as basis request - ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'peera' AND host = 'dynamic'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE host = 'XX.XX.XX.XX' AND callbackextension = 'peerb' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE host = 'XX.XX.XX.XX' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE ipaddr = 'XX.XX.XX.XX' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.XX' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.XX' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Allocating new SIP dialog for 6a419a3360e41dad4daf7df6598df636@XX.XX.XX.ZZ:5060 - NOTIFY (No RTP)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: SIP call-id changed from '6a419a3360e41dad4daf7df6598df636@XX.XX.XX.ZZ:5060' to '431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Scheduling destruction of SIP dialog '431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Initializing initreq for method NOTIFY - callid 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  0 [ 49]: NOTIFY sip:peera@XX.XX.XX.XX:51984;ob SIP/2.0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  1 [ 62]: Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK68c05e66;rport
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  3 [ 58]: From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as0a5e34c2
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  4 [ 40]: To: <sip:peera@XX.XX.XX.XX:51984;ob>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  5 [ 40]: Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  6 [ 58]: Call-ID: 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  7 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  8 [ 44]: User-Agent: Asterisk PBX GIT-master-b3914dfM
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  9 [ 22]: Event: message-summary
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header 10 [ 48]: Content-Type: application/simple-message-summary
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:51984:
NOTIFY sip:peera@XX.XX.XX.XX:51984;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK68c05e66;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as0a5e34c2
To: <sip:peera@XX.XX.XX.XX:51984;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #1174
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: -REALTIME- loading peer from database to memory. Name: peera. Peer objects: 0
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found peer 'peera' for 'peera' from XX.XX.XX.XX:51984
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: 
<--- Reliably Transmitting (NAT) to XX.XX.XX.XX:51984 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XX.XX.XX.XX:51984;branch=z9hG4bKPj1a5b51f2-125e-45af-a5ff-664c7c5eb837;received=XX.XX.XX.XX;rport=51984
From: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
To: sip:peerb@XX.XX.XX.ZZ;tag=as50191bb2
Call-ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21863 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="47a22126"
Content-Length: 0


<------------>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #1518
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Scheduling destruction of SIP dialog 'ae975bff-38df-408d-9c0a-6acb9bfdce6d' in 32000 ms (Method: INVITE)
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK68c05e66
i: 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as0a5e34c2
t: <sip:peera@XX.XX.XX.XX;ob>;tag=z9hG4bK68c05e66
CSeq: 102 NOTIFY
l: 0

<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK68c05e66
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 55]: f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as0a5e34c2
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 53]: t: <sip:peera@XX.XX.XX.XX;ob>;tag=z9hG4bK68c05e66
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060 (Checking To) --From tag as0a5e34c2 --To-tag z9hG4bK68c05e66  
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1174
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Stopping retransmission on '431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060' of Request 102: Match Found
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Got 200 accepted on NOTIFY 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Destroying SIP dialog 431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: Really destroying SIP dialog '431b2e580f436374296a46b40e0d3f32@XX.XX.XX.ZZ:5060' Method: NOTIFY
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
ACK sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj1a5b51f2-125e-45af-a5ff-664c7c5eb837
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
t: sip:peerb@XX.XX.XX.ZZ;tag=as50191bb2
i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21863 ACK
l: 0

LOG PART 4



<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: ACK sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj1a5b51f2-125e-45af-a5ff-664c7c5eb837
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 38]: t: sip:peerb@XX.XX.XX.ZZ;tag=as50191bb2
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [ 15]: CSeq: 21863 ACK
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  7 [  4]: l: 0
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (8 headers 0 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d (Checking From) --From tag 66803ece-05ba-4f03-8848-79a1fd8eb4bd --To-tag as50191bb2  
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1518
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Stopping retransmission on 'ae975bff-38df-408d-9c0a-6acb9bfdce6d' of Response 21863: Match Found
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
t: sip:peerb@XX.XX.XX.ZZ
m: <sip:peera@XX.XX.XX.XX:51984;ob>
i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21864 INVITE
k: replaces, 100rel, timer, norefersub
x: 1800
Min-SE: 90
User-Agent: Android test agent
Authorization: Digest username="peera", realm="asterisk", nonce="47a22126", uri="sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP", response="6a4aeba0f33e13192f5dc9d864f77017", algorithm=MD5
c: application/sdp
l: 346

v=0
o=- 3718074645 3718074645 IN IP4 172.16.14.26
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 37240 RTP/AVP 18 9 96
c=IN IP4 172.16.14.26
b=TIAS:64000
b=RS:0
b=RR:0
a=sendrecv
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ice-ufrag:3a89920f
a=ice-pwd:1c87a1b7
a=candidate:Hac100e1a 1 UDP 2130706431 172.16.14.26 37240 typ host
<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 54]: INVITE sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 23]: t: sip:peerb@XX.XX.XX.ZZ
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: m: <sip:peera@XX.XX.XX.XX:51984;ob>
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [ 39]: i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  7 [ 18]: CSeq: 21864 INVITE
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  8 [ 38]: k: replaces, 100rel, timer, norefersub
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  9 [  7]: x: 1800
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 10 [ 10]: Min-SE: 90
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 11 [ 30]: User-Agent: Android test agent
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 12 [182]: Authorization: Digest username="peera", realm="asterisk", nonce="47a22126", uri="sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP", response="6a4aeba0f33e13192f5dc9d864f77017", algorithm=MD5
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 13 [ 18]: c: application/sdp
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 14 [  6]: l: 346
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header 15 [  0]: 
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  0 [  3]: v=0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  1 [ 45]: o=- 3718074645 3718074645 IN IP4 172.16.14.26
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  2 [  9]: s=pjmedia
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  3 [  7]: b=AS:84
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  4 [  5]: t=0 0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  5 [  9]: a=X-nat:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  6 [ 29]: m=audio 37240 RTP/AVP 18 9 96
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  7 [ 21]: c=IN IP4 172.16.14.26
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  8 [ 12]: b=TIAS:64000
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body  9 [  6]: b=RS:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 10 [  6]: b=RR:0
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 11 [ 10]: a=sendrecv
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 12 [ 32]: a=rtpmap:96 telephone-event/8000
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 13 [ 14]: a=fmtp:96 0-16
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 14 [ 20]: a=ice-ufrag:3a89920f
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 15 [ 18]: a=ice-pwd:1c87a1b7
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:    Body 16 [ 66]: a=candidate:Hac100e1a 1 UDP 2130706431 172.16.14.26 37240 typ host
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (15 headers 17 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d (Checking From) --From tag 66803ece-05ba-4f03-8848-79a1fd8eb4bd --To-tag   
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ:5060' into...
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port '5060'.
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: Splitting 'XX.XX.XX.ZZ:5060' into...
[2017-10-27 08:30:46] DEBUG[26821] netsock2.c: ...host 'XX.XX.XX.ZZ' and port '5060'.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.XX:51984' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.XX' and port '51984'.
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Sending to XX.XX.XX.XX:51984 (NAT)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Initializing initreq for method INVITE - callid ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Using INVITE request as basis request - ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'peera' AND host = 'dynamic'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE host = 'XX.XX.XX.XX' AND callbackextension = 'peerb' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE host = 'XX.XX.XX.XX' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE ipaddr = 'XX.XX.XX.XX' AND port = '51984'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.XX' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.XX' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Allocating new SIP dialog for 51cba80a217eb0ac67dd95285f0fd7b7@XX.XX.XX.ZZ:5060 - NOTIFY (No RTP)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: SIP call-id changed from '51cba80a217eb0ac67dd95285f0fd7b7@XX.XX.XX.ZZ:5060' to '7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Scheduling destruction of SIP dialog '7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060' in 32000 ms (Method: NOTIFY)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Initializing initreq for method NOTIFY - callid 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  0 [ 49]: NOTIFY sip:peera@XX.XX.XX.XX:51984;ob SIP/2.0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  1 [ 62]: Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK13751b54;rport
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  3 [ 58]: From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as05b208b8
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  4 [ 40]: To: <sip:peera@XX.XX.XX.XX:51984;ob>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  5 [ 40]: Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  6 [ 58]: Call-ID: 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  7 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  8 [ 44]: User-Agent: Asterisk PBX GIT-master-b3914dfM
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header  9 [ 22]: Event: message-summary
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c:  Header 10 [ 48]: Content-Type: application/simple-message-summary
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:51984:
NOTIFY sip:peera@XX.XX.XX.XX:51984;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK13751b54;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as05b208b8
To: <sip:peera@XX.XX.XX.XX:51984;ob>
Contact: <sip:asterisk@XX.XX.XX.ZZ:5060>
Call-ID: 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX GIT-master-b3914dfM
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 91

Messages-Waiting: no
Message-Account: sip:asterisk@XX.XX.XX.ZZ
Voice-Message: 0/0 (0/0)

---
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #357
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: -REALTIME- loading peer from database to memory. Name: peera. Peer objects: 0
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found peer 'peera' for 'peera' from XX.XX.XX.XX:51984
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8b4089c8d8'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Allocated port 11490 for RTP instance '0x7f8b4089c8d8'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: RTP instance '0x7f8b4089c8d8' is setup and ready to go
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8b401874d8'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Allocated port 16268 for RTP instance '0x7f8b401874d8'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: RTP instance '0x7f8b401874d8' is setup and ready to go
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'Asterisk-99' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'Asterisk-99' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f8b401874d8'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] netsock2.c: Using SIP VIDEO CoS mark 6
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'Asterisk-99' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'Asterisk-99' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f8b4089c8d8'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] netsock2.c: Using SIP RTP CoS mark 5
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Setting NAT on RTP to On
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Setting NAT on VRTP to On
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP o=- 3718074645 3718074645 IN IP4 172.16.14.26... OK.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found RTP audio format 18
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f8b4e613000
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found RTP audio format 9
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f8b4e613000
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found RTP audio format 96
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Setting tx payload type 96 based on m type on 0x7f8b4e613000
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting '172.16.14.26' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host '172.16.14.26' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 172.16.14.26... OK.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP b=RS:0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP b=RR:0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Found audio description format telephone-event for ID 96
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-16... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:3a89920f... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:1c87a1b7... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=candidate:Hac100e1a 1 UDP 2130706431 172.16.14.26 37240 typ host... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x176b350) from 0x7f8b4e613000 to 0x7f8b4e613000
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x176b530) from 0x7f8b4e613000 to 0x7f8b4e613000
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Crossover copying tx to rx payload mapping 96 (0x7f8b400470a0) from 0x7f8b4e613000 to 0x7f8b4e613000
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Capabilities: us - (g729|g722|h264), peer - audio=(g722|g729)/video=(nothing)/text=(nothing), combined - (g729|g722)
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] acl.c: For destination '172.16.14.26', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f8b4089c8d8'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Peer audio RTP is at port 172.16.14.26:37240
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying rx payload mapping 9 (0x176b350) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying rx payload mapping 18 (0x176b530) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying rx payload mapping 96 (0x7f8b400470a0) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying tx payload mapping 9 (0x176b350) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying tx payload mapping 18 (0x176b530) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Copying tx payload mapping 96 (0x7f8b400470a0) from 0x7f8b4e613000 to 0x7f8b4089caa0
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f8b4089c8d8'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Peer doesn't provide video
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: We're settling with these formats: (g729|g722)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Checking SIP call limits for device peera
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Updating call counter for incoming call
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Call from peer 'peera' is 1 out of 2147483647
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.ZZ:5060' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.ZZ' into...
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.ZZ' and port ''.
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peera
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: Looking for peerb in sip-ctx (domain XX.XX.XX.ZZ)
[2017-10-27 08:30:46] DEBUG[26802] chan_sip.c: Checking device state for peer peera
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: Changing state for SIP/peera - state 2 (In use)
[2017-10-27 08:30:46] DEBUG[26854] 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-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'peerb' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Incoming INVITE with 'timer' option supported
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: INVITE also has "Session-Expires" header.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Session-Expires: 1800
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: INVITE also has "Min-SE" header.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Received Min-SE: 90
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] channel.c: Channel 0x7f8b4021b918 'SIP/peera-000000db' allocated
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** Our native formats are (g729) 
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** Joint capabilities are (g729|g722) 
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** Our capabilities are (g729|g722|h264) 
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** AST_CODEC_CHOOSE formats are g729 
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] rtp_engine.c: Destroyed RTP instance '0x7f8b401874d8'
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: This channel will not be able to handle video.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'peerb' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] sip/route.c: sip_route_dump: route/path hop: <sip:peera@XX.XX.XX.XX:51984;ob>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: SIP/peera-000000db: New call is still down.... Trying... 
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:51984 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP XX.XX.XX.XX:51984;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1;received=XX.XX.XX.XX;rport=51984
From: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
To: sip:peerb@XX.XX.XX.ZZ
Call-ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21864 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:peerb@XX.XX.XX.ZZ:5060>
Content-Length: 0

LOG PART 5


<------------>
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'peerb' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'peerb' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] pbx_variables.c: Result of 'EXTEN' is 'peerb'
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] pbx_realtime.c: Executing [peerb@sip-ctx:1] Gosub("SIP/peera-000000db", "chexec,1(peerb)")
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'chanexec' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] app_stack.c: Channel SIP/peera-000000db has no datastore, so we're allocating one.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] app_stack.c: Setting 'ARG1' to 'peerb'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'chanexec' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peera
[2017-10-27 08:30:46] DEBUG[26802] chan_sip.c: Checking device state for peer peera
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: Changing state for SIP/peera - state 2 (In use)
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'chanexec' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] pbx_realtime.c: Executing [chexec@sip-ctx:2] Dial("SIP/peera-000000db", "SIP/peerb")
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Asked to create a SIP channel with formats: (g729)
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Allocating new SIP dialog for 29eb785d481f18eb07ac75304720eee3@XX.XX.XX.ZZ:5060 - INVITE (No RTP)
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_rtp_asterisk.c: Allocated port 17548 for RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: RTP instance '0x7f8bc0000d58' is setup and ready to go
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f8bc000d198'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_rtp_asterisk.c: Allocated port 14178 for RTP instance '0x7f8bc000d198'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: RTP instance '0x7f8bc000d198' is setup and ready to go
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] netsock2.c: Splitting 'Asterisk-99' into...
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] netsock2.c: ...host 'Asterisk-99' and port ''.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f8bc000d198'
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] netsock2.c: Using SIP VIDEO CoS mark 6
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] netsock2.c: Splitting 'Asterisk-99' into...
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] netsock2.c: ...host 'Asterisk-99' and port ''.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] netsock2.c: Using SIP RTP CoS mark 5
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Setting NAT on RTP to On
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Setting NAT on VRTP to On
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] acl.c: For destination 'XX.XX.XX.XX', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Setting AST_TRANSPORT_UDP with address XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Setting NAT on RTP to On
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Setting NAT on VRTP to On
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: SIP call-id changed from '29eb785d481f18eb07ac75304720eee3@XX.XX.XX.ZZ:5060' to '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Channel 0x7f8bc0014208 'SIP/peerb-000000dc' allocated
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** Our native formats are (g729) 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** Joint capabilities are (g729) 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** Our capabilities are (g729|g722|h264) 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** AST_CODEC_CHOOSE formats are g729 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** Our preferred formats from the incoming channel are (g729) 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: Destroyed RTP instance '0x7f8bc000d198'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: This channel will not be able to handle video.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' ESCAPE '\\' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel_internal_api.c: Channel Call ID changing from [C-000001c9] to [C-000001c9]
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Outgoing Call for peerb
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Updating call counter for outgoing call
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Call to peer 'peerb' is 1 out of 2147483647
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:46] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 6 (Ringing)
[2017-10-27 08:30:46] DEBUG[26854] app_queue.c: Device 'SIP/peerb' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: This call needs video offers, but there's no video support enabled!
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: ** Our capability: (g729|g722|h264) Video flag: False Text flag: False
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: ** Our prefcodec: (g729) 
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: Audio is at 17548
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: Adding codec g729 to SDP
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: Adding codec g722 to SDP
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: -- Done with adding codecs to SDP
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Done building SDP. Settling with this capability: (g729|g722|h264)
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Initializing initreq for method INVITE - callid 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  0 [ 47]: INVITE sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  1 [ 62]: Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK531076c8;rport
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  3 [ 45]: From: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  4 [ 38]: To: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  5 [ 38]: Contact: <sip:peera@XX.XX.XX.ZZ:5060>
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  6 [ 58]: Call-ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  7 [ 16]: CSeq: 102 INVITE
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  8 [ 44]: User-Agent: Asterisk PBX GIT-master-b3914dfM
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header  9 [ 35]: Date: Fri, 27 Oct 2017 
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header 11 [ 26]: Supported: replaces, timer
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c:  Header 12 [ 29]: Content-Type: application/sdp
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:50499:
INVITE sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK531076c8;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
To: <sip:peerb@XX.XX.XX.XX:50499;ob>
Contact: <sip:peera@XX.XX.XX.ZZ:5060>
Call-ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX GIT-master-b3914dfM
Date: Fri, 27 Oct 2017
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 297

v=0
o=root 1565982607 1565982607 IN IP4 XX.XX.XX.ZZ
s=Asterisk PBX GIT-master-b3914dfM
c=IN IP4 XX.XX.XX.ZZ
t=0 0
m=audio 17548 RTP/AVP 18 9 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv
---
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #1602
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] app_dial.c: Called SIP/peerb
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Channel SIP/peerb-000000dc setting read format path: g729 -> g729
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Channel SIP/peera-000000db setting write format path: g729 -> g729
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Channel SIP/peera-000000db setting read format path: g729 -> g729
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Channel SIP/peerb-000000dc setting write format path: g729 -> g729
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:128.199.76.204:45492 --->

<------------->
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK13751b54
i: 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as05b208b8
t: <sip:peera@XX.XX.XX.XX;ob>;tag=z9hG4bK13751b54
CSeq: 102 NOTIFY
l: 0

<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK13751b54
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 55]: f: "asterisk" <sip:asterisk@XX.XX.XX.ZZ>;tag=as05b208b8
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 53]: t: <sip:peera@XX.XX.XX.XX;ob>;tag=z9hG4bK13751b54
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 NOTIFY
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060 (Checking To) --From tag as05b208b8 --To-tag z9hG4bK13751b54  
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #357
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Stopping retransmission on '7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060' of Request 102: Match Found
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Got 200 accepted on NOTIFY 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: Destroying SIP dialog 7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: Really destroying SIP dialog '7b354ef85d405a59283a061e4a19000f@XX.XX.XX.ZZ:5060' Method: NOTIFY
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:51.36.60.139:1462 --->

<------------->
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
t: <sip:peerb@XX.XX.XX.XX;ob>
CSeq: 102 INVITE
l: 0

<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 18]: SIP/2.0 100 Trying
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 42]: f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 31]: t: <sip:peerb@XX.XX.XX.XX;ob>
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060 (Checking To) --From tag as723e8d57 --To-tag   
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: *** SIP TIMER: Cancelling retransmission #1602 - INVITE (got response)
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' Request 102: Found
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: SIP response 100 to standard invite
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 180 Ringing
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
CSeq: 102 INVITE
m: <sip:peerb@XX.XX.XX.XX:50499;ob>
l: 0

<------------->
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  0 [ 19]: SIP/2.0 180 Ringing
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  3 [ 42]: f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  4 [ 72]: t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  6 [ 37]: m: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c:  Header  7 [  4]: l: 0
[2017-10-27 08:30:46] VERBOSE[26821] chan_sip.c: --- (8 headers 0 lines) ---
[2017-10-27 08:30:46] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060 (Checking To) --From tag as723e8d57 --To-tag 56133670-9248-4411-ae78-5928db3bf2d4  
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' Request 102: Found
[2017-10-27 08:30:46] DEBUG[26821][C-000001c9] chan_sip.c: SIP response 180 to standard invite
[2017-10-27 08:30:46] VERBOSE[26821][C-000001c9] sip/route.c: sip_route_dump: route/path hop: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:46] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:46] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 6 (Ringing)
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] app_dial.c: SIP/peerb-000000dc is ringing
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] rtp_engine.c: Setting early bridge SDP of 'SIP/peera-000000db' with that of 'SIP/peerb-000000dc'
[2017-10-27 08:30:46] VERBOSE[44689][C-000001c9] chan_sip.c: 
<--- Transmitting (NAT) to XX.XX.XX.XX:51984 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP XX.XX.XX.XX:51984;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1;received=XX.XX.XX.XX;rport=51984
From: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
To: sip:peerb@XX.XX.XX.ZZ;tag=as20be5bd0
Call-ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21864 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:peerb@XX.XX.XX.ZZ:5060>
Content-Length: 0


<------------>
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Driver for channel 'SIP/peera-000000db' does not support indication 3, emulating it
[2017-10-27 08:30:46] WARNING[44689][C-000001c9] channel.c: Unable to find a codec translation path: (slin) -> (g729)
[2017-10-27 08:30:46] WARNING[44689][C-000001c9] indications.c: Unable to set 'SIP/peera-000000db' to signed linear format (write)
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] channel.c: Prodding channel 'SIP/peera-000000db'
[2017-10-27 08:30:46] DEBUG[44689][C-000001c9] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2017-10-27 08:30:46] WARNING[44689][C-000001c9] channel.c: Unable to handle indication 3 for 'SIP/peera-000000db'
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:45685 --->

[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:47489 --->

<------------->
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
CSeq: 102 INVITE
m: <sip:peerb@XX.XX.XX.XX:50499;ob>
k: replaces, 100rel, timer, norefersub
c: application/sdp
l: 220

v=0
o=- 3718074650 3718074651 IN IP4 XX.XX.XX.XY
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 39059 RTP/AVP 9 101
c=IN IP4 XX.XX.XX.XY
b=TIAS:64000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

LOG PART 6


<------------->
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK531076c8
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  3 [ 42]: f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  4 [ 72]: t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  6 [ 37]: m: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  7 [ 38]: k: replaces, 100rel, timer, norefersub
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  8 [ 18]: c: application/sdp
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  9 [  6]: l: 220
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header 10 [  0]: 
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  0 [  3]: v=0
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  1 [ 45]: o=- 3718074650 3718074651 IN IP4 XX.XX.XX.XY
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  2 [  9]: s=pjmedia
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  3 [  7]: b=AS:84
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  4 [  5]: t=0 0
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  5 [  9]: a=X-nat:0
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  6 [ 27]: m=audio 39059 RTP/AVP 9 101
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  7 [ 21]: c=IN IP4 XX.XX.XX.XY
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  8 [ 12]: b=TIAS:64000
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body  9 [ 10]: a=sendrecv
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body 10 [ 33]: a=rtpmap:101 telephone-event/8000
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:    Body 11 [ 15]: a=fmtp:101 0-16
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: --- (10 headers 12 lines) ---
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060 (Checking To) --From tag as723e8d57 --To-tag 56133670-9248-4411-ae78-5928db3bf2d4  
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Acked pending invite 102
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Stopping retransmission on '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' of Request 102: Match Found
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: SIP response 200 to standard invite
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP o=- 3718074650 3718074651 IN IP4 XX.XX.XX.XY... OK.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Found RTP audio format 9
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f8b4e612150
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Found RTP audio format 101
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f8b4e612150
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] netsock2.c: Splitting 'XX.XX.XX.XY' into...
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] netsock2.c: ...host 'XX.XX.XX.XY' and port ''.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 XX.XX.XX.XY... OK.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Found audio description format telephone-event for ID 101
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Capabilities: us - (g729|g722|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722)
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] acl.c: For destination 'XX.XX.XX.XY', our source address is 'XX.XX.XX.ZZ'.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Peer audio RTP is at port XX.XX.XX.XY:39059
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] rtp_engine.c: Copying tx payload mapping 9 (0x176b350) from 0x7f8b4e612150 to 0x7f8bc0000f20
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] rtp_engine.c: Copying tx payload mapping 101 (0x176fdf0) from 0x7f8b4e612150 to 0x7f8bc0000f20
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: We're settling with these formats: (g722)
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: We have an owner, now see if we need to change this call
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g729)
[2017-10-27 08:30:49] WARNING[26821][C-000001c9] channel.c: Unable to find a codec translation path: (g722) -> (g729)
[2017-10-27 08:30:49] WARNING[26821][C-000001c9] channel.c: Unable to find a codec translation path: (g729) -> (g722)
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Updating call counter for outgoing call
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] sip/route.c: sip_route_dump: route/path hop: <sip:peerb@XX.XX.XX.XX:50499;ob>
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 2 (In use)
[2017-10-27 08:30:49] DEBUG[26854] app_queue.c: Device 'SIP/peerb' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Strict routing enforced for session 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] VERBOSE[26821][C-000001c9] chan_sip.c: Transmitting (NAT) to XX.XX.XX.XX:50499:
ACK sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK52c6805c;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
To: <sip:peerb@XX.XX.XX.XX:50499;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
Contact: <sip:peera@XX.XX.XX.ZZ:5060>
Call-ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX GIT-master-b3914dfM
Content-Length: 0


---
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Trying to put 'ACK sip:pee' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] app_dial.c: SIP/peerb-000000dc answered SIP/peera-000000db
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] rtp_engine.c: Setting early bridge SDP of 'SIP/peera-000000db' with that of 'SIP/peerb-000000dc'
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 2 (In use)
[2017-10-27 08:30:49] WARNING[44689][C-000001c9] channel.c: No path to translate from SIP/peerb-000000dc to SIP/peera-000000db
[2017-10-27 08:30:49] WARNING[44689][C-000001c9] app_dial.c: Had to drop call because I couldn't make SIP/peera-000000db compatible with SIP/peerb-000000dc
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] channel.c: Channel 0x7f8bc0014208 'SIP/peerb-000000dc' hanging up.  Refs: 2
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Hangup call SIP/peerb-000000dc, SIP callid 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: update_call_counter(peerb) - decrement call limit counter on hangup
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Updating call counter for outgoing call
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Call to peer 'peerb' removed from call limit 2147483647
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] chan_sip.c: Scheduling destruction of SIP dialog '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' in 32000 ms (Method: INVITE)
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 1 (Not in use)
[2017-10-27 08:30:49] DEBUG[26854] app_queue.c: Device 'SIP/peerb' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Strict routing enforced for session 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] chan_sip.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:50499:
BYE sip:peerb@XX.XX.XX.XX:50499;ob SIP/2.0
Via: SIP/2.0/UDP XX.XX.XX.ZZ:5060;branch=z9hG4bK64be71f9;rport
Max-Forwards: 70
From: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
To: <sip:peerb@XX.XX.XX.XX:50499;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
Call-ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
CSeq: 103 BYE
User-Agent: Asterisk PBX GIT-master-b3914dfM
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #701
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Trying to put 'BYE sip:pee' onto UDP socket destined for XX.XX.XX.XX:50499
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] channel.c: Channel 0x7f8bc0014208 'SIP/peerb-000000dc' destroying
[2017-10-27 08:30:49] DEBUG[26806] cdr.c: Finalized CDR for SIP/peerb-000000dc - start 1509085846.372884 answer 1509085849.694678 end 1509085849.696299 dispo ANSWERED
[2017-10-27 08:30:49] DEBUG[26806] cdr.c: CDR for SIP/peerb-000000dc is dialed and has no Party B; discarding
[2017-10-27 08:30:49] DEBUG[26806] cdr.c: Finalized CDR for SIP/peera-000000db - start 1509085846.365246 answer 0.000000 end 1509085849.696474 dispo ANSWERED
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peerb
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peerb
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peerb - state 1 (Not in use)
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] pbx.c: Spawn extension (sip-ctx,chexec,2) exited non-zero on 'SIP/peera-000000db'
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] pbx.c: Spawn extension (sip-ctx, chexec, 2) exited non-zero on 'SIP/peera-000000db'
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] channel.c: Soft-Hanging (0x10) up channel 'SIP/peera-000000db'
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND priority = '1' AND context = 'sip-ctx'
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Connection okay.
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%' ESCAPE '\\' AND priority = '1' AND context = 'sip-ctx' ORDER BY exten
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] channel.c: Channel 0x7f8b4021b918 'SIP/peera-000000db' hanging up.  Refs: 2
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Hangup call SIP/peera-000000db, SIP callid ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: update_call_counter(peera) - decrement call limit counter on hangup
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Updating call counter for incoming call
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Call from peer 'peera' removed from call limit 2147483647
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Hanging up channel in state Ring (not UP)
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] chan_sip.c: Scheduling destruction of SIP dialog 'ae975bff-38df-408d-9c0a-6acb9bfdce6d' in 32000 ms (Method: INVITE)
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: AST hangup cause 16 (no match found in SIP)
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peera
[2017-10-27 08:30:49] VERBOSE[44689][C-000001c9] chan_sip.c: 
<--- Reliably Transmitting (NAT) to XX.XX.XX.XX:51984 --->
SIP/2.0 603 Declined
Via: SIP/2.0/UDP XX.XX.XX.XX:51984;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1;received=XX.XX.XX.XX;rport=51984
From: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
To: sip:peerb@XX.XX.XX.ZZ;tag=as20be5bd0
Call-ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21864 INVITE
Server: Asterisk PBX GIT-master-b3914dfM
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0


<------------>
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peera
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #1558
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peera - state 1 (Not in use)
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] chan_sip.c: Trying to put 'SIP/2.0 603' onto UDP socket destined for XX.XX.XX.XX:51984
[2017-10-27 08:30:49] DEBUG[44689][C-000001c9] channel.c: Channel 0x7f8b4021b918 'SIP/peera-000000db' destroying
[2017-10-27 08:30:49] DEBUG[26854] app_queue.c: Device 'SIP/peera' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-10-27 08:30:49] DEBUG[26806] 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 ('"" <peera>','peera','peerb','sip-ctx','SIP/peera-000000db','SIP/peerb-000000dc','Dial','SIP/peerb','2017-10-27 08:30:46','2017-10-27 08:30:49','3','0','ANSWERED','DOCUMENTATION','1509085846.377')
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: No provider found, checking channel drivers for SIP - peera
[2017-10-27 08:30:49] DEBUG[26802] chan_sip.c: Checking device state for peer peera
[2017-10-27 08:30:49] DEBUG[26802] devicestate.c: Changing state for SIP/peera - state 1 (Not in use)
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:50499 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK64be71f9
i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
CSeq: 103 BYE
l: 0

<------------->
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  1 [ 86]: v: SIP/2.0/UDP XX.XX.XX.ZZ:5060;rport=5060;received=XX.XX.XX.ZZ;branch=z9hG4bK64be71f9
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  2 [ 52]: i: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  3 [ 42]: f: <sip:peera@XX.XX.XX.ZZ>;tag=as723e8d57
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  4 [ 72]: t: <sip:peerb@XX.XX.XX.XX;ob>;tag=56133670-9248-4411-ae78-5928db3bf2d4
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  5 [ 13]: CSeq: 103 BYE
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  6 [  4]: l: 0
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: --- (7 headers 0 lines) ---
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c: = Looking for  Call ID: 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060 (Checking To) --From tag as723e8d57 --To-tag 56133670-9248-4411-ae78-5928db3bf2d4  
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #701
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Stopping retransmission on '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' of Request 103: Match Found
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c: Destroying SIP dialog 334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: Really destroying SIP dialog '334f15dc6d73db8e11a522c206a15678@XX.XX.XX.ZZ:5060' Method: INVITE
[2017-10-27 08:30:49] DEBUG[26821] rtp_engine.c: Destroyed RTP instance '0x7f8bc0000d58'
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: 
<--- SIP read from UDP:XX.XX.XX.XX:51984 --->
ACK sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1
Max-Forwards: 70
f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
t: sip:peerb@XX.XX.XX.ZZ;tag=as20be5bd0
i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
CSeq: 21864 ACK
l: 0

<------------->
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  0 [ 51]: ACK sip:peerb@XX.XX.XX.ZZ:5060;transport=UDP SIP/2.0
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  1 [ 94]: v: SIP/2.0/UDP XX.XX.XX.XX:51984;rport;branch=z9hG4bKPj7a72cd30-10fa-4efd-af58-ffb42808f7d1
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  3 [ 66]: f: sip:peera@XX.XX.XX.ZZ;tag=66803ece-05ba-4f03-8848-79a1fd8eb4bd
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  4 [ 38]: t: sip:peerb@XX.XX.XX.ZZ;tag=as20be5bd0
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  5 [ 39]: i: ae975bff-38df-408d-9c0a-6acb9bfdce6d
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  6 [ 15]: CSeq: 21864 ACK
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c:  Header  7 [  4]: l: 0
[2017-10-27 08:30:49] VERBOSE[26821] chan_sip.c: --- (8 headers 0 lines) ---
[2017-10-27 08:30:49] DEBUG[26821] chan_sip.c: = Looking for  Call ID: ae975bff-38df-408d-9c0a-6acb9bfdce6d (Checking From) --From tag 66803ece-05ba-4f03-8848-79a1fd8eb4bd --To-tag as20be5bd0  
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1558
[2017-10-27 08:30:49] DEBUG[26821][C-000001c9] chan_sip.c: Stopping retransmission on 'ae975bff-38df-408d-9c0a-6acb9bfdce6d' of Response 21864: Match Found

It would have helped if you had removed all the REGISTERs and NOTIFY’s from the logs!

It looks like there has been a change in chan_sip.c, sometime after Asterisk 1.8, to only allow one native format for a peer. I don’t know the reason for that, although I suspect it was for this sort of case, were there were missing codecs.

My guess is that you need specify g722 first in your list of codecs, if you want Asterisk to use it, where possible. I’m assuming that will make Asterisk choose g722 as the native format, if it is available.

As already noted, if you have phones that only do g729, there is no way they will communicate with g722 only phones, without your installing (and licensing) the codec.

To get a better idea of why the change was made, you would need to look at the history of chan_sip, see when the change was made, and look at the bug report and or code review associated with that change.

We don’t have such phones. As stated earlier, we only have two types of phones. Type A have both g729 and g722. Type B have only g722.

We listed g722 before g729 in sip.conf. All phones were able to talk successfully (A ↔ A, A ↔ B, B ↔ A, and B ↔ B). The problem is that g729 is never being selected anymore, which we don’t want. What we actually want is g729 to be used whenever possible, that’s when both peers support it (that’s if both phones are of type A), and we want g722 to be used whenever at least one peer does not offer g729.

There must be a way to achieve this. Your help is greatly appreciated.

Thanks

The chan_sip module provides dialplan variables[1] that can be used to influence the codec negotiation process, that is the extent of the control possible. Each leg is independently negotiated otherwise. (Phone A to Asterisk, Asterisk to Phone B - not Phone A with what Phone B supports and such). The foundation has been put into place in 15 to do more powerful things, but they don’t yet exist there either.

[1] https://wiki.asterisk.org/wiki/display/AST/chan_sip+Channel+Variables

1 Like

We will look into it. Thanks.

Asterisk is behaving as expected.
You need to add g729 codec. You can use opensource implementation of g729 from the below link and reload the module. It should support G729A transcoding.
[removed by Board Admin]