
<--- SIP read from UDP:192.168.1.147:43521 --->
INVITE sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.g2BgJ-5gq;rport
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: sip:350001@192.168.1.227
CSeq: 20 INVITE
Call-ID: hbjlrmc7uS
Max-Forwards: 70
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 335
Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)

v=0
o=50001 3653 2040 IN IP4 192.168.41.102
s=Talk
c=IN IP4 192.168.41.102
b=AS:200
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7080 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
m=video 9078 RTP/AVP 96
a=rtpmap:96 VP8/90000
<------------->
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 40]: INVITE sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.g2BgJ-5gq;rport
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 29]: To: sip:350001@192.168.1.227
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 15]: CSeq: 20 INVITE
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 19]: Supported: outbound
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 89]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 29]: Content-Type: application/sdp
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [ 19]: Content-Length: 335
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [106]: Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 12 [ 44]: User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 13 [  0]: 
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  0 [  3]: v=0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  1 [ 39]: o=50001 3653 2040 IN IP4 192.168.41.102
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  2 [  6]: s=Talk
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  3 [ 23]: c=IN IP4 192.168.41.102
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  4 [  8]: b=AS:200
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  5 [  5]: t=0 0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  6 [ 72]: a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  7 [ 27]: m=audio 7080 RTP/AVP 96 101
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  8 [ 24]: a=rtpmap:96 opus/48000/2
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  9 [ 24]: a=fmtp:96 useinbandfec=1
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 10 [ 34]: a=rtpmap:101 telephone-event/48000
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 11 [ 23]: m=video 9078 RTP/AVP 96
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body 12 [ 21]: a=rtpmap:96 VP8/90000
--- (13 headers 13 lines) ---
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag   
[Feb 20 15:08:27] DEBUG[32283]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:3877 ast_sip_ouraddrfor: Target address 192.168.1.147:43521 is not local, substituting externaddr
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.227:5060
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:43521' into...
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '43521'.
Sending to 192.168.1.147:43521 (no NAT)
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9006 __sip_alloc: Allocating new SIP dialog for hbjlrmc7uS - INVITE (No RTP)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: outbound"
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -outbound-
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: outbound
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:43521' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '43521'.
Sending to 192.168.1.147:43521 (no NAT)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:26104 handle_request_invite: Initializing initreq for method INVITE - callid hbjlrmc7uS
Using INVITE request as basis request - hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Found peer '50001' for '50001' from 192.168.1.147:43521

<--- Reliably Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.g2BgJ-5gq;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: sip:350001@192.168.1.227;tag=as0e760435
Call-ID: hbjlrmc7uS
CSeq: 20 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="511d2592"
Content-Length: 0


<------------>
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:4266 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #6
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.147:43521
Scheduling destruction of SIP dialog 'hbjlrmc7uS' in 32000 ms (Method: INVITE)

<--- SIP read from UDP:192.168.1.147:43521 --->
ACK sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.g2BgJ-5gq;rport
Call-ID: hbjlrmc7uS
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as0e760435
Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
Max-Forwards: 70
CSeq: 20 ACK

<------------->
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 37]: ACK sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.g2BgJ-5gq;rport
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 46]: To: <sip:350001@192.168.1.227>;tag=as0e760435
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [106]: Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 12]: CSeq: 20 ACK
--- (8 headers 0 lines) ---
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag as0e760435  
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:4526 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'hbjlrmc7uS' of Response 20: Match Found

<--- SIP read from UDP:192.168.1.147:43521 --->
INVITE sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.1yFdd3ui0;rport
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: sip:350001@192.168.1.227
CSeq: 21 INVITE
Call-ID: hbjlrmc7uS
Max-Forwards: 70
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 335
Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227", response="fa25ad5cd56246350c19e0c6ce654859"

v=0
o=50001 3653 2040 IN IP4 192.168.41.102
s=Talk
c=IN IP4 192.168.41.102
b=AS:200
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7080 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
m=video 9078 RTP/AVP 96
a=rtpmap:96 VP8/90000
<------------->
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 40]: INVITE sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.1yFdd3ui0;rport
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 29]: To: sip:350001@192.168.1.227
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 15]: CSeq: 21 INVITE
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 19]: Supported: outbound
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 89]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 29]: Content-Type: application/sdp
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [ 19]: Content-Length: 335
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [106]: Contact: <sip:50001@192.168.1.147:43521>;+sip.instance="<urn:uuid:b8a7aef2-6c08-499e-ace8-966b5e4775ca>"
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 12 [ 44]: User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 13 [167]: Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227", response="fa25ad5cd56246350c19e0c6ce654859"
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 14 [  0]: 
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  0 [  3]: v=0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  1 [ 39]: o=50001 3653 2040 IN IP4 192.168.41.102
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  2 [  6]: s=Talk
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  3 [ 23]: c=IN IP4 192.168.41.102
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  4 [  8]: b=AS:200
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  5 [  5]: t=0 0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  6 [ 72]: a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  7 [ 27]: m=audio 7080 RTP/AVP 96 101
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  8 [ 24]: a=rtpmap:96 opus/48000/2
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  9 [ 24]: a=fmtp:96 useinbandfec=1
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 10 [ 34]: a=rtpmap:101 telephone-event/48000
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 11 [ 23]: m=video 9078 RTP/AVP 96
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body 12 [ 21]: a=rtpmap:96 VP8/90000
--- (14 headers 13 lines) ---
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag   
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:43521' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '43521'.
Sending to 192.168.1.147:43521 (no NAT)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:26104 handle_request_invite: Initializing initreq for method INVITE - callid hbjlrmc7uS
Using INVITE request as basis request - hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Found peer '50001' for '50001' from 192.168.1.147:43521
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f04f803b548'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 18038 for RTP instance '0x7f04f803b548'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:18038 (18038) for RTP instance '0x7f04f803b548'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f04f803b548' is setup and ready to go
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f04f803e408'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 13192 for RTP instance '0x7f04f803e408'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:13192 (13192) for RTP instance '0x7f04f803e408'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f04f803e408' is setup and ready to go
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'iZ94rhgsz5zZ' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'iZ94rhgsz5zZ' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f04f803e408'
  == Using SIP VIDEO CoS mark 6
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'iZ94rhgsz5zZ' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'iZ94rhgsz5zZ' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f04f803b548'
  == Using SIP RTP CoS mark 5
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:5798 do_setnat: Setting NAT on RTP to On
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:5802 do_setnat: Setting NAT on VRTP to On
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP o=50001 3653 2040 IN IP4 192.168.41.102... OK.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.102' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.102' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP c=IN IP4 192.168.41.102... OK.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP b=AS:200... UNSUPPORTED OR FAILED.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10271 process_sdp: Processing session-level SDP a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics... UNSUPPORTED OR FAILED.
Found RTP audio format 96
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f04b6f98080
Found RTP audio format 101
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f04b6f98080
Found audio description format opus for ID 96
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=rtpmap:96 opus/48000/2... OK.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=fmtp:96 useinbandfec=1... OK.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 101 on 0x7f04b6f98080
Found unknown media description format telephone-event for ID 101
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/48000... UNSUPPORTED OR FAILED.
Found RTP video format 96
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f04b6f98010
Found video description format VP8 for ID 96
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtpmap:96 VP8/90000... OK.
Capabilities: us - (opus|vp8), peer - audio=(opus)/video=(vp8)/text=(nothing), combined - (opus|vp8)
Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: acl.c:957 ast_ouraddrfor: For destination '192.168.41.102', our source address is '192.168.41.78'.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803b548'
Peer audio RTP is at port 192.168.41.102:7080
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 96 (0x7f04f803b170) from 0x7f04b6f98080 to 0x7f04f803b710
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:4916 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f04f803b548'
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:853 ast_rtp_ice_set_role: Set role to CONTROLLED (0x7f04f803e408)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:856 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7f04f803e408)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: acl.c:957 ast_ouraddrfor: For destination '192.168.41.102', our source address is '192.168.41.78'.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803e408'
Peer video RTP is at port 192.168.41.102:9078
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 96 (0x7f04f80408d0) from 0x7f04b6f98010 to 0x7f04f803e5d0
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:11022 process_sdp: We're settling with these formats: (opus|vp8)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:26236 handle_request_invite: Checking SIP call limits for device 50001
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Looking for 350001 in default (domain 192.168.1.227)
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8153 sip_new: *** Our native formats are (vp8|opus) 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8154 sip_new: *** Joint capabilities are (opus|vp8) 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8155 sip_new: *** Our capabilities are (opus|vp8) 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8156 sip_new: *** Prefcaps capabilities are (nothing) 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8157 sip_new: *** AST_CODEC_CHOOSE formats are opus 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8169 sip_new: *** *************   SIP_PAGE2_VIDEOSUPPORT_ALWAYS *********** 
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:8197 sip_new: This channel can handle video! HOLLYWOOD next!
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
sip_route_dump: route/path hop: <sip:50001@192.168.1.147:43521>
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:26440 handle_request_invite: SIP/50001-00000002: New call is still down.... Trying... 

<--- Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.1yFdd3ui0;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: sip:350001@192.168.1.227
Call-ID: hbjlrmc7uS
CSeq: 21 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:350001@192.168.1.227:5060>
Content-Length: 0


<------------>
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.147:43521
[Feb 20 15:08:27] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 50001
[Feb 20 15:08:27] DEBUG[32233]: chan_sip.c:30178 sip_devicestate: Checking device state for peer 50001
[Feb 20 15:08:27] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for SIP/50001 - state 1 (Not in use)
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'Playback'
    -- Executing [350001@default:1] Playback("SIP/50001-00000002", "beep") in new stack
[Feb 20 15:08:27] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 50001
[Feb 20 15:08:27] DEBUG[32233]: chan_sip.c:30178 sip_devicestate: Checking device state for peer 50001
[Feb 20 15:08:27] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for SIP/50001 - state 1 (Not in use)
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:7412 sip_answer: SIP answering channel: SIP/50001-00000002
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13392 add_sdp: This call needs video offers!
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13416 add_sdp: ** Our capability: (opus|vp8) Video flag: False Text flag: True
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13417 add_sdp: ** Our prefcodec: (nothing) 
Audio is at 18038
Video is at 192.168.1.227:13192
Adding codec opus to SDP
Adding video codec vp8 to SDP
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13587 add_sdp: -- Done with adding codecs to SDP
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13612 add_sdp: Setting framing on incoming call: 0
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:13800 add_sdp: Done building SDP. Settling with this capability: (opus|vp8)

<--- Reliably Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.1yFdd3ui0;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: sip:350001@192.168.1.227;tag=as33378e50
Call-ID: hbjlrmc7uS
CSeq: 21 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:350001@192.168.1.227:5060>
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 1707018762 1707018762 IN IP4 192.168.1.227
s=Asterisk PBX 13.14.0
c=IN IP4 192.168.1.227
b=CT:384
t=0 0
m=audio 18038 RTP/AVP 96
a=rtpmap:96 opus/48000/2
a=maxptime:20
a=sendrecv
m=video 13192 RTP/AVP 96
a=rtpmap:96 VP8/90000
a=rtcp-fb:* ccm fir
a=sendrecv

<------------>
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:4266 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #10
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:43521

<--- SIP read from UDP:192.168.1.147:43521 --->
ACK sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:43521;rport;branch=z9hG4bK.ypqff633F
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
CSeq: 21 ACK
Call-ID: hbjlrmc7uS
Max-Forwards: 70
Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227", response="fa25ad5cd56246350c19e0c6ce654859"

<------------->
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 42]: ACK sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:43521;rport;branch=z9hG4bK.ypqff633F
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as33378e50
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 12]: CSeq: 21 ACK
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [167]: Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227", response="fa25ad5cd56246350c19e0c6ce654859"
--- (8 headers 0 lines) ---
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag as33378e50  
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:4526 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'hbjlrmc7uS' of Response 21: Match Found
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f804c5c0 -- Probation learning mode pass with source address 192.168.1.147:8897
       > 0x7f04f804c5c0 -- Probation passed - setting RTP source address to 192.168.1.147:8897
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803b548'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting write format path: gsm -> opus
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to opus
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <SIP/50001-00000002> Playing 'beep.gsm' (language 'en')
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f804c5c0 -- Probation learning mode pass with source address 192.168.1.147:8897
       > 0x7f04f804c5c0 -- Probation passed - setting RTP source address to 192.168.1.147:8897
[Feb 20 15:08:27] DEBUG[32248]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32249]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32250]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32241]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 7
[Feb 20 15:08:27] DEBUG[32241]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 8
[Feb 20 15:08:27] DEBUG[32241]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 9
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f804f020 -- Probation learning mode pass with source address 192.168.1.147:8929
       > 0x7f04f804f020 -- Probation passed - setting RTP source address to 192.168.1.147:8929
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803e408'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f804f020 -- Probation learning mode pass with source address 192.168.1.147:8929
       > 0x7f04f804f020 -- Probation passed - setting RTP source address to 192.168.1.147:8929
[Feb 20 15:08:27] DEBUG[32252]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32221]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 11
[Feb 20 15:08:27] DEBUG[32253]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32254]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:27] DEBUG[32221]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 12
[Feb 20 15:08:27] DEBUG[32221]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 13
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting write format path: opus -> opus
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:2
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'Answer'
    -- Executing [350001@default:2] Answer("SIP/50001-00000002", "") in new stack
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:3
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '50001'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'Set'
    -- Executing [350001@default:3] Set("SIP/50001-00000002", "CID=350001") in new stack
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:4
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'CID' is '350001'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '350001'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [350001@default:4] GotoIf("SIP/50001-00000002", "1?cme") in new stack
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:0
    -- Goto (default,350001,8)
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:8
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '350001'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: pbx.c:2875 pbx_extension_helper: Launching 'ConfBridge'
    -- Executing [350001@default:8] ConfBridge("SIP/50001-00000002", "350001,default_bridge_32,default_useradmin,sample_user_menu") in new stack
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: app_confbridge.c:1422 join_conference_bridge: Trying to find conference bridge '350001'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:496 find_best_technology: Bridge technology native_rtp does not have any capabilities we want.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:496 find_best_technology: Bridge technology simple_bridge does not have any capabilities we want.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:515 find_best_technology: Chose bridge technology softmix
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:794 bridge_base_init: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: calling softmix technology constructor
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:802 bridge_base_init: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: calling softmix technology start
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge_roles.c:272 setup_bridge_role: Set role 'announcer'
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: app_confbridge.c:1367 alloc_playback_chan: Created announcer channel 'CBAnn/350001-00000001;1' to conference bridge '350001'
[Feb 20 15:08:27] DEBUG[32322]: bridge_softmix.c:1099 softmix_mixing_thread: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: starting mixing thread
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: app_confbridge.c:1524 join_conference_bridge: Created conference '350001' and linked to container.
[Feb 20 15:08:27] DEBUG[32305]: app_queue.c:2482 device_state_cb: Device 'confbridge:350001' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: confbridge/conf_state.c:84 conf_change_state: Changing conference '350001' state from EMPTY to SINGLE_MARKED
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: app_confbridge.c:1145 conf_update_user_mute: User SIP/50001-00000002 is unmuted: user:0 system:0.
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x20a2878(SIP/50001-00000002) is joining
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pushing 0x20a2878(SIP/50001-00000002)
    -- Channel SIP/50001-00000002 joined 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: bridge.c:432 bridge_channel_complete_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x20a2878(SIP/50001-00000002) is joining softmix technology
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:5444 ast_set_read_format_path: Channel SIP/50001-00000002 setting read format path: opus -> slin
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting write format path: slin -> opus
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 960, ms is 40
[Feb 20 15:08:27] DEBUG[32324]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04f4478c88(CBAnn/350001-00000001;2) is joining
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32324]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pushing 0x7f04f4478c88(CBAnn/350001-00000001;2)
[Feb 20 15:08:27] DEBUG[32324]: bridge_roles.c:272 setup_bridge_role: Set role 'announcer'
    -- Channel CBAnn/350001-00000001;2 joined 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:27] DEBUG[32324]: bridge.c:432 bridge_channel_complete_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04f4478c88(CBAnn/350001-00000001;2) is joining softmix technology
[Feb 20 15:08:27] DEBUG[32324]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 20 15:08:27] DEBUG[32324]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: gsm -> slin
[Feb 20 15:08:27] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <CBAnn/350001-00000001;1> Playing 'confbridge-join.gsm' (language 'en')
       > Video source in bridge '350001' (a5f5d270-9cf6-415f-9eec-9e3a746f2b7e) is now 'SIP/50001-00000002' (1487574507.6)
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to vp8
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 41670, ms is 33 (2970), pred/ts/samples 49770/8100/2700
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160

<--- SIP read from UDP:192.168.1.147:43521 --->
INFO sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.Of4DukVyW;rport
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
CSeq: 22 INFO
Call-ID: hbjlrmc7uS
Max-Forwards: 70
Content-Type: application/media_control+xml
Content-Length: 185
User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="c48bf6f91b58a34bf282c790e3000159"

<?xml version="1.0" encoding="utf-8" ?><media_control> <vc_primitive> <to_encoder> <picture_fast_update></picture_fast_update> </to_encoder> </vc_primitive></media_control>
<------------->
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 43]: INFO sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 67]: Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.Of4DukVyW;rport
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as33378e50
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 13]: CSeq: 22 INFO
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 43]: Content-Type: application/media_control+xml
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 19]: Content-Length: 185
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 44]: User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [172]: Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="c48bf6f91b58a34bf282c790e3000159"
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [  0]: 
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body  0 [172]: <?xml version="1.0" encoding="utf-8" ?><media_control> <vc_primitive> <to_encoder> <picture_fast_update></picture_fast_update> </to_encoder> </vc_primitive></media_control>
--- (11 headers 1 lines) ---
[Feb 20 15:08:27] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag as33378e50  
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received INFO (13) - Command in SIP INFO
Receiving INFO!

<--- Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.Of4DukVyW;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
Call-ID: hbjlrmc7uS
CSeq: 22 INFO
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 20 15:08:27] DEBUG[32283][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:43521
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:27] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:28] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:28] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:28] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: slin -> slin
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32289]: res_pjsip_registrar_expire.c:78 check_expiration_thread: Woke up at 1487574508  Interval: 30
[Feb 20 15:08:28] DEBUG[32289]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32251]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:28] DEBUG[32221]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 10
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:28] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:28] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:28] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:28] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:28] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:29] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:29] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:29] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:29] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:29] DEBUG[32246]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:29] DEBUG[32247]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Feb 20 15:08:29] DEBUG[32241]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 5
[Feb 20 15:08:29] DEBUG[32241]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 6
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160

<--- SIP read from UDP:192.168.1.147:23681 --->


<------------->
[Feb 20 15:08:30] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [  0]: 
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:30] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:31] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:31] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:31] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:31] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160

<--- SIP read from UDP:192.168.1.147:23681 --->
INVITE sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.WDQVvXpCa;rport
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: sip:350001@192.168.1.227
CSeq: 20 INVITE
Call-ID: Z-69URbOvz
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 468
Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)

v=0
o=50002 3789 3674 IN IP4 192.168.41.114
s=Talk
c=IN IP4 192.168.41.114
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7078 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
a=rtcp-fb:* trr-int 5000
m=video 9078 RTP/AVP 96
a=rtpmap:96 VP8/90000
a=rtcp-fb:* trr-int 5000
a=rtcp-fb:96 nack pli
a=rtcp-fb:96 nack sli
a=rtcp-fb:96 ack rpsi
a=rtcp-fb:96 ccm fir
<------------->
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 40]: INVITE sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.WDQVvXpCa;rport
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 29]: To: sip:350001@192.168.1.227
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 15]: CSeq: 20 INVITE
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 29]: Supported: replaces, outbound
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 89]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 29]: Content-Type: application/sdp
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [ 19]: Content-Length: 468
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [120]: Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 12 [ 45]: User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 13 [  0]: 
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  0 [  3]: v=0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  1 [ 39]: o=50002 3789 3674 IN IP4 192.168.41.114
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  2 [  6]: s=Talk
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  3 [ 23]: c=IN IP4 192.168.41.114
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  4 [  5]: t=0 0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  5 [ 72]: a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  6 [ 27]: m=audio 7078 RTP/AVP 96 101
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  7 [ 24]: a=rtpmap:96 opus/48000/2
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  8 [ 24]: a=fmtp:96 useinbandfec=1
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  9 [ 34]: a=rtpmap:101 telephone-event/48000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 10 [ 24]: a=rtcp-fb:* trr-int 5000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 11 [ 23]: m=video 9078 RTP/AVP 96
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 12 [ 21]: a=rtpmap:96 VP8/90000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 13 [ 24]: a=rtcp-fb:* trr-int 5000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 14 [ 21]: a=rtcp-fb:96 nack pli
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 15 [ 21]: a=rtcp-fb:96 nack sli
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 16 [ 21]: a=rtcp-fb:96 ack rpsi
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body 17 [ 20]: a=rtcp-fb:96 ccm fir
--- (13 headers 18 lines) ---
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: Z-69URbOvz (Checking From) --From tag 72D6s4BnS --To-tag   
[Feb 20 15:08:31] DEBUG[32283]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:3877 ast_sip_ouraddrfor: Target address 192.168.1.147:23681 is not local, substituting externaddr
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:3910 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.227:5060
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:23681' into...
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '23681'.
Sending to 192.168.1.147:23681 (no NAT)
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9006 __sip_alloc: Allocating new SIP dialog for Z-69URbOvz - INVITE (No RTP)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:28652 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: replaces, outbound"
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces-
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -outbound-
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: outbound
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:23681' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '23681'.
Sending to 192.168.1.147:23681 (no NAT)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:26104 handle_request_invite: Initializing initreq for method INVITE - callid Z-69URbOvz
Using INVITE request as basis request - Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Found peer '50002' for '50002' from 192.168.1.147:23681

<--- Reliably Transmitting (no NAT) to 192.168.1.147:23681 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.WDQVvXpCa;received=192.168.1.147;rport=23681
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: sip:350001@192.168.1.227;tag=as3c4ef99f
Call-ID: Z-69URbOvz
CSeq: 20 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="13c1f3f5"
Content-Length: 0


<------------>
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:4266 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #7
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.147:23681
Scheduling destruction of SIP dialog 'Z-69URbOvz' in 32000 ms (Method: INVITE)
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160

<--- SIP read from UDP:192.168.1.147:23681 --->
ACK sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.WDQVvXpCa;rport
Call-ID: Z-69URbOvz
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: <sip:350001@192.168.1.227>;tag=as3c4ef99f
Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
Max-Forwards: 70
CSeq: 20 ACK

<------------->
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 37]: ACK sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.WDQVvXpCa;rport
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 19]: Call-ID: Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 46]: To: <sip:350001@192.168.1.227>;tag=as3c4ef99f
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [120]: Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 12]: CSeq: 20 ACK
--- (8 headers 0 lines) ---
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: Z-69URbOvz (Checking From) --From tag 72D6s4BnS --To-tag as3c4ef99f  
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:28652 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:4526 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'Z-69URbOvz' of Response 20: Match Found

<--- SIP read from UDP:192.168.1.147:23681 --->
INVITE sip:350001@192.168.1.227 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.-yE4vr3AG;rport
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: sip:350001@192.168.1.227
CSeq: 21 INVITE
Call-ID: Z-69URbOvz
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 468
Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227", response="b15ef0f60d60d635d7da7df91eac07e1"

v=0
o=50002 3789 3674 IN IP4 192.168.41.114
s=Talk
c=IN IP4 192.168.41.114
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7078 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
a=rtcp-fb:* trr-int 5000
m=video 9078 RTP/AVP 96
a=rtpmap:96 VP8/90000
a=rtcp-fb:* trr-int 5000
a=rtcp-fb:96 nack pli
a=rtcp-fb:96 nack sli
a=rtcp-fb:96 ack rpsi
a=rtcp-fb:96 ccm fir
<------------->
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 40]: INVITE sip:350001@192.168.1.227 SIP/2.0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.-yE4vr3AG;rport
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 29]: To: sip:350001@192.168.1.227
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 15]: CSeq: 21 INVITE
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 29]: Supported: replaces, outbound
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 89]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 29]: Content-Type: application/sdp
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [ 19]: Content-Length: 468
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [120]: Contact: <sip:50002@192.168.1.147:23681;transport=udp>;+sip.instance="<urn:uuid:a4202cbb-957b-4d85-b706-715e5b02ac72>"
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 12 [ 45]: User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 13 [167]: Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227", response="b15ef0f60d60d635d7da7df91eac07e1"
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 14 [  0]: 
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  0 [  3]: v=0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  1 [ 39]: o=50002 3789 3674 IN IP4 192.168.41.114
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  2 [  6]: s=Talk
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  3 [ 23]: c=IN IP4 192.168.41.114
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  4 [  5]: t=0 0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  5 [ 72]: a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  6 [ 27]: m=audio 7078 RTP/AVP 96 101
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  7 [ 24]: a=rtpmap:96 opus/48000/2
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  8 [ 24]: a=fmtp:96 useinbandfec=1
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body  9 [ 34]: a=rtpmap:101 telephone-event/48000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 10 [ 24]: a=rtcp-fb:* trr-int 5000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 11 [ 23]: m=video 9078 RTP/AVP 96
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 12 [ 21]: a=rtpmap:96 VP8/90000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 13 [ 24]: a=rtcp-fb:* trr-int 5000
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 14 [ 21]: a=rtcp-fb:96 nack pli
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 15 [ 21]: a=rtcp-fb:96 nack sli
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:    Body 16 [ 21]: a=rtcp-fb:96 ack rpsi
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body 17 [ 20]: a=rtcp-fb:96 ccm fir
--- (14 headers 18 lines) ---
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: Z-69URbOvz (Checking From) --From tag 72D6s4BnS --To-tag   
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:28652 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:23681' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '23681'.
Sending to 192.168.1.147:23681 (no NAT)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:26104 handle_request_invite: Initializing initreq for method INVITE - callid Z-69URbOvz
Using INVITE request as basis request - Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Found peer '50002' for '50002' from 192.168.1.147:23681
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f04f8052358'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 11142 for RTP instance '0x7f04f8052358'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:11142 (11142) for RTP instance '0x7f04f8052358'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f04f8052358' is setup and ready to go
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:2681 ast_rtp_new: Allocated port 18724 for RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:2708 ast_rtp_new: Creating ICE session 0.0.0.0:18724 (18724) for RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f04f802b5e8' is setup and ready to go
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'iZ94rhgsz5zZ' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'iZ94rhgsz5zZ' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f04f802b5e8'
  == Using SIP VIDEO CoS mark 6
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'iZ94rhgsz5zZ' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'iZ94rhgsz5zZ' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:4967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f04f8052358'
  == Using SIP RTP CoS mark 5
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:5798 do_setnat: Setting NAT on RTP to On
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:5802 do_setnat: Setting NAT on VRTP to On
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP o=50002 3789 3674 IN IP4 192.168.41.114... OK.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.114' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.114' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP c=IN IP4 192.168.41.114... OK.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10271 process_sdp: Processing session-level SDP a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics... UNSUPPORTED OR FAILED.
Found RTP audio format 96
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f04b6f98080
Found RTP audio format 101
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f04b6f98080
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
Found audio description format opus for ID 96
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=rtpmap:96 opus/48000/2... OK.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=fmtp:96 useinbandfec=1... OK.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:791 ast_rtp_codecs_payloads_unset: Unsetting payload 101 on 0x7f04b6f98080
Found unknown media description format telephone-event for ID 101
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/48000... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (audio) SDP a=rtcp-fb:* trr-int 5000... UNSUPPORTED OR FAILED.
Found RTP video format 96
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:684 ast_rtp_codecs_payloads_set_m_type: Don't have a default tx payload type 96 format for m type on 0x7f04b6f98010
Found video description format VP8 for ID 96
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtpmap:96 VP8/90000... OK.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtcp-fb:* trr-int 5000... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtcp-fb:96 nack pli... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtcp-fb:96 nack sli... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtcp-fb:96 ack rpsi... UNSUPPORTED OR FAILED.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:10726 process_sdp: Processing media-level (video) SDP a=rtcp-fb:96 ccm fir... UNSUPPORTED OR FAILED.
Capabilities: us - (opus|vp8), peer - audio=(opus)/video=(vp8)/text=(nothing), combined - (opus|vp8)
Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: acl.c:957 ast_ouraddrfor: For destination '192.168.41.114', our source address is '192.168.41.78'.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f8052358'
Peer audio RTP is at port 192.168.41.114:7078
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 96 (0x7f04f8048990) from 0x7f04b6f98080 to 0x7f04f8052520
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:4916 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f04f8052358'
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:853 ast_rtp_ice_set_role: Set role to CONTROLLED (0x7f04f802b5e8)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:856 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7f04f802b5e8)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: acl.c:957 ast_ouraddrfor: For destination '192.168.41.114', our source address is '192.168.41.78'.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f802b5e8'
Peer video RTP is at port 192.168.41.114:9078
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 96 (0x7f04f8023e90) from 0x7f04b6f98010 to 0x7f04f802b7b0
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:11022 process_sdp: We're settling with these formats: (opus|vp8)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:26236 handle_request_invite: Checking SIP call limits for device 50002
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:6767 update_call_counter: Updating call counter for incoming call
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.227' into...
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.227' and port ''.
Looking for 350001 in default (domain 192.168.1.227)
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8153 sip_new: *** Our native formats are (vp8|opus) 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8154 sip_new: *** Joint capabilities are (opus|vp8) 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8155 sip_new: *** Our capabilities are (opus|vp8) 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8156 sip_new: *** Prefcaps capabilities are (nothing) 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8157 sip_new: *** AST_CODEC_CHOOSE formats are opus 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8169 sip_new: *** *************   SIP_PAGE2_VIDEOSUPPORT_ALWAYS *********** 
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:8197 sip_new: This channel can handle video! HOLLYWOOD next!
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
sip_route_dump: route/path hop: <sip:50002@192.168.1.147:23681;transport=udp>
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:26440 handle_request_invite: SIP/50002-00000003: New call is still down.... Trying... 

<--- Transmitting (no NAT) to 192.168.1.147:23681 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.-yE4vr3AG;received=192.168.1.147;rport=23681
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: sip:350001@192.168.1.227
Call-ID: Z-69URbOvz
CSeq: 21 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:350001@192.168.1.227:5060>
Content-Length: 0


<------------>
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.147:23681
[Feb 20 15:08:31] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 50002
[Feb 20 15:08:31] DEBUG[32233]: chan_sip.c:30178 sip_devicestate: Checking device state for peer 50002
[Feb 20 15:08:31] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for SIP/50002 - state 1 (Not in use)
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:1
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@demo:1
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'Playback'
    -- Executing [350001@default:1] Playback("SIP/50002-00000003", "beep") in new stack
[Feb 20 15:08:31] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 50002
[Feb 20 15:08:31] DEBUG[32233]: chan_sip.c:30178 sip_devicestate: Checking device state for peer 50002
[Feb 20 15:08:31] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for SIP/50002 - state 1 (Not in use)
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:7412 sip_answer: SIP answering channel: SIP/50002-00000003
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13392 add_sdp: This call needs video offers!
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13416 add_sdp: ** Our capability: (opus|vp8) Video flag: False Text flag: True
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13417 add_sdp: ** Our prefcodec: (nothing) 
Audio is at 11142
Video is at 192.168.1.227:18724
Adding codec opus to SDP
Adding video codec vp8 to SDP
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13587 add_sdp: -- Done with adding codecs to SDP
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13612 add_sdp: Setting framing on incoming call: 0
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:13800 add_sdp: Done building SDP. Settling with this capability: (opus|vp8)

<--- Reliably Transmitting (no NAT) to 192.168.1.147:23681 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.-yE4vr3AG;received=192.168.1.147;rport=23681
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: sip:350001@192.168.1.227;tag=as3ccad9dc
Call-ID: Z-69URbOvz
CSeq: 21 INVITE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:350001@192.168.1.227:5060>
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 1787129777 1787129777 IN IP4 192.168.1.227
s=Asterisk PBX 13.14.0
c=IN IP4 192.168.1.227
b=CT:384
t=0 0
m=audio 11142 RTP/AVP 96
a=rtpmap:96 opus/48000/2
a=maxptime:20
a=sendrecv
m=video 18724 RTP/AVP 96
a=rtpmap:96 VP8/90000
a=rtcp-fb:* ccm fir
a=sendrecv

<------------>
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:4266 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #13
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:23681
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 8280, ms is 155 (13950), pred/ts/samples 387450/379170/5400
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 14580, ms is 3 (270), pred/ts/samples 379170/393750/6300
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160

<--- SIP read from UDP:192.168.1.147:23681 --->
ACK sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:23681;rport;branch=z9hG4bK.OtIDHFYeA
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: <sip:350001@192.168.1.227>;tag=as3ccad9dc
CSeq: 21 ACK
Call-ID: Z-69URbOvz
Max-Forwards: 70
Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227", response="b15ef0f60d60d635d7da7df91eac07e1"
User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)

<------------->
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 42]: ACK sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:23681;rport;branch=z9hG4bK.OtIDHFYeA
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as3ccad9dc
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 12]: CSeq: 21 ACK
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: Z-69URbOvz
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [167]: Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227", response="b15ef0f60d60d635d7da7df91eac07e1"
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 45]: User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
--- (9 headers 0 lines) ---
[Feb 20 15:08:31] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: Z-69URbOvz (Checking From) --From tag 72D6s4BnS --To-tag as3ccad9dc  
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:28652 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:4526 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13
[Feb 20 15:08:31] DEBUG[32283][C-00000003]: chan_sip.c:4537 __sip_ack: Stopping retransmission on 'Z-69URbOvz' of Response 21: Match Found
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f805d2a0 -- Probation learning mode pass with source address 192.168.1.147:9313
       > 0x7f04f805d2a0 -- Probation passed - setting RTP source address to 192.168.1.147:9313
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f8052358'
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting write format path: gsm -> opus
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to opus
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <SIP/50002-00000003> Playing 'beep.gsm' (language 'en')
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f805d2a0 -- Probation learning mode pass with source address 192.168.1.147:9313
       > 0x7f04f805d2a0 -- Probation passed - setting RTP source address to 192.168.1.147:9313
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:31] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 672, ms is 34
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 7200, ms is 53 (4770), pred/ts/samples 434070/426870/3600
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 720, ms is 5
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 672, ms is 6
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting write format path: opus -> opus
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:2
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'Answer'
    -- Executing [350001@default:2] Answer("SIP/50002-00000003", "") in new stack
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:3
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '50002'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'Set'
    -- Executing [350001@default:3] Set("SIP/50002-00000003", "CID=350002") in new stack
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:4
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'CID' is '350002'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '350001'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [350001@default:4] GotoIf("SIP/50002-00000003", "0?cme") in new stack
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:5
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'CID' is '350002'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'exten' is NULL
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [350001@default:5] GotoIf("SIP/50002-00000003", "350002 = ") in new stack
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up 350001@default:6
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '350001'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: pbx.c:2875 pbx_extension_helper: Launching 'ConfBridge'
    -- Executing [350001@default:6] ConfBridge("SIP/50002-00000003", "350001,default_bridge_32,default_user,sample_user_menu") in new stack
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: app_confbridge.c:1422 join_conference_bridge: Trying to find conference bridge '350001'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: app_confbridge.c:1145 conf_update_user_mute: User SIP/50001-00000002 is unmuted: user:0 system:0.
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: app_confbridge.c:1145 conf_update_user_mute: User SIP/50002-00000003 is unmuted: user:0 system:0.
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: confbridge/conf_state.c:84 conf_change_state: Changing conference '350001' state from SINGLE_MARKED to MULTI_MARKED
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04fc0231e8(SIP/50002-00000003) is joining
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pushing 0x7f04fc0231e8(SIP/50002-00000003)
    -- Channel SIP/50002-00000003 joined 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:32] DEBUG[32234]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/50002-00000003 - start 1487574511.480298 answer 1487574511.490104 end 1487574512.104325 dispo ANSWERED
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: bridge.c:432 bridge_channel_complete_join: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04fc0231e8(SIP/50002-00000003) is joining softmix technology
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:5444 ast_set_read_format_path: Channel SIP/50002-00000003 setting read format path: opus -> slin
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting write format path: slin -> opus
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3052 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 20 15:08:32] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: gsm -> slin
[Feb 20 15:08:32] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <CBAnn/350001-00000001;1> Playing 'confbridge-join.gsm' (language 'en')
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 1152, ms is 44
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3625 ast_rtp_write: Ooh, format changed from none to vp8
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 7200, ms is 10 (900), pred/ts/samples 900/8100/8100
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3469 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f8057ad0 -- Probation learning mode pass with source address 192.168.1.147:9377
       > 0x7f04f8057ad0 -- Probation passed - setting RTP source address to 192.168.1.147:9377
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.147', our source address is '192.168.41.78'.
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4564 ast_rtp_read: 0x7f04f8057ad0 -- Probation learning mode pass with source address 192.168.1.147:9377
       > 0x7f04f8057ad0 -- Probation passed - setting RTP source address to 192.168.1.147:9377
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 400590, ms is 22 (1980), pred/ts/samples 44280/444870/2700
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3408 ast_rtp_raw_write: Difference is 440190, ms is 71 (6390), pred/ts/samples 447390/7200/6300
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:32] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: slin -> slin
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:32] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
       > Video source in bridge '350001' (a5f5d270-9cf6-415f-9eec-9e3a746f2b7e) is now 'SIP/50002-00000003' (1487574511.9)
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:32] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 124 bytes
[Feb 20 15:08:33] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9345' into...
[Feb 20 15:08:33] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9345'.
[Feb 20 15:08:33] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:11143' into...
[Feb 20 15:08:33] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '11143'.
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32322]: bridge_softmix.c:860 analyse_softmix_stats: Multiple above internal rate.  Bridge changed from 8000 to 48000.
[Feb 20 15:08:33] DEBUG[32321][C-00000002]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32325][C-00000003]: translate.c:600 ast_translate: Sample size different 960 vs 160
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5444 ast_set_read_format_path: Channel SIP/50001-00000002 setting read format path: opus -> slin48
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting write format path: slin48 -> opus
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=960, hits_required=21
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=960, hits_required=116
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5444 ast_set_read_format_path: Channel CBAnn/350001-00000001;2 setting read format path: slin -> slin48
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;2 setting write format path: slin48 -> slin
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=960, hits_required=21
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=960, hits_required=116
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5444 ast_set_read_format_path: Channel SIP/50002-00000003 setting read format path: opus -> slin48
[Feb 20 15:08:33] DEBUG[32322]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting write format path: slin48 -> opus
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=960, hits_required=21
[Feb 20 15:08:33] DEBUG[32322]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=960, hits_required=116

<--- SIP read from UDP:192.168.1.147:43521 --->


<------------->
[Feb 20 15:08:34] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [  0]: 
[Feb 20 15:08:34] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:34] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 124 bytes
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9409' into...
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9409'.
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18725' into...
[Feb 20 15:08:34] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18725'.
[Feb 20 15:08:35] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:35] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 124 bytes
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9345' into...
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9345'.
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:11143' into...
[Feb 20 15:08:35] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '11143'.
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:11143' into...
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '11143'.
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9345' into...
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9345'.

<--- SIP read from UDP:192.168.1.147:43521 --->
INFO sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.qc523AA9L;rport
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
CSeq: 23 INFO
Call-ID: hbjlrmc7uS
Max-Forwards: 70
Content-Type: application/media_control+xml
Content-Length: 185
User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="c48bf6f91b58a34bf282c790e3000159"

<?xml version="1.0" encoding="utf-8" ?><media_control> <vc_primitive> <to_encoder> <picture_fast_update></picture_fast_update> </to_encoder> </vc_primitive></media_control>
<------------->
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 43]: INFO sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 67]: Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.qc523AA9L;rport
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as33378e50
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 13]: CSeq: 23 INFO
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 43]: Content-Type: application/media_control+xml
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [ 19]: Content-Length: 185
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  9 [ 44]: User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 10 [172]: Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="c48bf6f91b58a34bf282c790e3000159"
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header 11 [  0]: 
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9930 parse_request:    Body  0 [172]: <?xml version="1.0" encoding="utf-8" ?><media_control> <vc_primitive> <to_encoder> <picture_fast_update></picture_fast_update> </to_encoder> </vc_primitive></media_control>
--- (11 headers 1 lines) ---
[Feb 20 15:08:36] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag as33378e50  
[Feb 20 15:08:36] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received INFO (13) - Command in SIP INFO
Receiving INFO!

<--- Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.41.102:5060;branch=z9hG4bK.qc523AA9L;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
Call-ID: hbjlrmc7uS
CSeq: 23 INFO
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 20 15:08:36] DEBUG[32283][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:43521
[Feb 20 15:08:36] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:36] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:37] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 960, ms is 40
[Feb 20 15:08:37] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 912, ms is 1
[Feb 20 15:08:37] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 1056, ms is 42
[Feb 20 15:08:37] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:3393 ast_rtp_raw_write: Difference is 912, ms is 1
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18725' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18725'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9409' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9409'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:37] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 124 bytes
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9409' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9409'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18725' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18725'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:37] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:37] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.
[Feb 20 15:08:38] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 124 bytes
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9345' into...
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9345'.
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:11143' into...
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '11143'.
[Feb 20 15:08:38] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9089' into...
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9089'.
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:18039' into...
[Feb 20 15:08:38] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '18039'.

<--- SIP read from UDP:192.168.1.147:23681 --->
BYE sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.IAMTz4DeL;rport
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: <sip:350001@192.168.1.227>;tag=as3ccad9dc
CSeq: 22 BYE
Call-ID: Z-69URbOvz
Max-Forwards: 70
User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227:5060", response="c826b6da3e65f4979670786ef5acd506"

<------------->
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 42]: BYE sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.IAMTz4DeL;rport
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as3ccad9dc
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 12]: CSeq: 22 BYE
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: Z-69URbOvz
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 45]: User-Agent: Linphone/3.10.2 (belle-sip/1.5.0)
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [172]: Authorization: Digest realm="asterisk", nonce="13c1f3f5", algorithm=MD5, username="50002", uri="sip:350001@192.168.1.227:5060", response="c826b6da3e65f4979670786ef5acd506"
--- (9 headers 0 lines) ---
[Feb 20 15:08:39] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: Z-69URbOvz (Checking From) --From tag 72D6s4BnS --To-tag as3ccad9dc  
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: chan_sip.c:28652 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: chan_sip.c:27096 handle_request_bye: Initializing initreq for method BYE - callid Z-69URbOvz
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:23681' into...
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '23681'.
Sending to 192.168.1.147:23681 (no NAT)
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: chan_sip.c:3409 sip_alreadygone: Setting SIP_ALREADYGONE on dialog Z-69URbOvz
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f8052358'
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f802b5e8'
Scheduling destruction of SIP dialog 'Z-69URbOvz' in 32000 ms (Method: BYE)
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: chan_sip.c:27259 handle_request_bye: Received bye, issuing owner hangup

<--- Transmitting (no NAT) to 192.168.1.147:23681 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.147:23681;branch=z9hG4bK.IAMTz4DeL;received=192.168.1.147;rport=23681
From: <sip:50002@192.168.1.227>;tag=72D6s4BnS
To: <sip:350001@192.168.1.227>;tag=as3ccad9dc
Call-ID: Z-69URbOvz
CSeq: 22 BYE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 20 15:08:39] DEBUG[32283][C-00000003]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:23681
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f04fc0231e8(SIP/50002-00000003) state from:0 to:1
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pulling 0x7f04fc0231e8(SIP/50002-00000003)
    -- Channel SIP/50002-00000003 left 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04fc0231e8(SIP/50002-00000003) is leaving softmix technology
[Feb 20 15:08:39] DEBUG[32234]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/50001-00000002 - start 1487574507.141745 answer 1487574507.151360 end 1487574519.478140 dispo ANSWERED
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: bridge_channel.c:336 ast_bridge_channel_restore_formats: Bridge is returning 0x7f04fc0231e8(SIP/50002-00000003) to read format opus
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting read format path: opus -> opus
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: bridge_channel.c:346 ast_bridge_channel_restore_formats: Bridge is returning 0x7f04fc0231e8(SIP/50002-00000003) to write format opus
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: channel.c:5680 set_format: Channel SIP/50002-00000003 setting write format path: opus -> opus
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: confbridge/conf_state.c:84 conf_change_state: Changing conference '350001' state from MULTI_MARKED to SINGLE_MARKED
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: app_confbridge.c:1145 conf_update_user_mute: User SIP/50001-00000002 is unmuted: user:0 system:0.
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: pbx.c:4321 __ast_pbx_run: Extension 350001, priority 6 returned normally even though call was hung up
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/50002-00000003'
[Feb 20 15:08:39] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: gsm -> slin
[Feb 20 15:08:39] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <CBAnn/350001-00000001;1> Playing 'confbridge-leave.gsm' (language 'en')
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up h@default:1
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: pbx_lua.c:1480 lua_find_extension: Looking up h@demo:1
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: channel.c:2728 ast_hangup: Hanging up channel 'SIP/50002-00000003'
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: chan_sip.c:7154 sip_hangup: Hangup call SIP/50002-00000003, SIP callid Z-69URbOvz
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f8052358'
[Feb 20 15:08:39] DEBUG[32325][C-00000003]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f802b5e8'
[Feb 20 15:08:39] DEBUG[32234]: cdr_radius.c:222 radius_log: Unable to create RADIUS record. CDR not recorded!
[Feb 20 15:08:39] DEBUG[32234]: res_config_sqlite.c:827 cdr_handler: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"" <50002>','50002','350001','default','SIP/50002-00000003','ConfBridge','350001,default_bridge_32,default_user,sample_user_menu','2017-02-20 15:08:31','2017-02-20 15:08:31','2017-02-20 15:08:32','0','0','ANSWERED','DOCUMENTATION','1487574511.9')
[Feb 20 15:08:39] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 50002
[Feb 20 15:08:39] DEBUG[32233]: chan_sip.c:30178 sip_devicestate: Checking device state for peer 50002
[Feb 20 15:08:39] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for SIP/50002 - state 1 (Not in use)
       > Video source in bridge '350001' (a5f5d270-9cf6-415f-9eec-9e3a746f2b7e) is now 'SIP/50001-00000002' (1487574507.6)
[Feb 20 15:08:39] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:39] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:39] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:39] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: slin -> slin
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:4361 __sip_autodestruct: Auto destroying SIP dialog '8~FxmoS1dn'
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:6589 sip_pvt_dtor: Destroying SIP dialog 8~FxmoS1dn
Really destroying SIP dialog '8~FxmoS1dn' Method: BYE
[Feb 20 15:08:40] DEBUG[32283]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x7f04f80423c8'
[Feb 20 15:08:40] DEBUG[32283]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x7f04f80405a8'
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: res_rtp_asterisk.c:4212 ast_rtcp_read: Got RTCP report of 104 bytes
[Feb 20 15:08:40] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:9153' into...
[Feb 20 15:08:40] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '9153'.
[Feb 20 15:08:40] DEBUG[32302]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.41.78:13193' into...
[Feb 20 15:08:40] DEBUG[32302]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.41.78' and port '13193'.

<--- SIP read from UDP:192.168.1.147:43521 --->
BYE sip:350001@192.168.1.227:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.9K5jXNs6G;rport
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
CSeq: 24 BYE
Call-ID: hbjlrmc7uS
Max-Forwards: 70
User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="e6196c2ec04090a086aeab34a7dcaf71"

<------------->
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [ 42]: BYE sip:350001@192.168.1.227:5060 SIP/2.0
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  1 [ 69]: Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.9K5jXNs6G;rport
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  2 [ 46]: From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  3 [ 46]: To: <sip:350001@192.168.1.227>;tag=as33378e50
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  4 [ 12]: CSeq: 24 BYE
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  5 [ 19]: Call-ID: hbjlrmc7uS
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  7 [ 44]: User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  8 [172]: Authorization: Digest realm="asterisk", nonce="511d2592", algorithm=MD5, username="50001", uri="sip:350001@192.168.1.227:5060", response="e6196c2ec04090a086aeab34a7dcaf71"
--- (9 headers 0 lines) ---
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9419 __find_call: = Looking for  Call ID: hbjlrmc7uS (Checking From) --From tag HtYjSiRga --To-tag as33378e50  
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: chan_sip.c:28652 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: chan_sip.c:27096 handle_request_bye: Initializing initreq for method BYE - callid hbjlrmc7uS
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.147:43521' into...
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.147' and port '43521'.
Sending to 192.168.1.147:43521 (no NAT)
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: chan_sip.c:3409 sip_alreadygone: Setting SIP_ALREADYGONE on dialog hbjlrmc7uS
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803b548'
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: res_rtp_asterisk.c:5036 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f04f803e408'
Scheduling destruction of SIP dialog 'hbjlrmc7uS' in 32000 ms (Method: BYE)
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: chan_sip.c:27259 handle_request_bye: Received bye, issuing owner hangup

<--- Transmitting (no NAT) to 192.168.1.147:43521 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.147:43521;branch=z9hG4bK.9K5jXNs6G;received=192.168.1.147;rport=43521
From: <sip:50001@192.168.1.227>;tag=HtYjSiRga
To: <sip:350001@192.168.1.227>;tag=as33378e50
Call-ID: hbjlrmc7uS
CSeq: 24 BYE
Server: Asterisk PBX 13.14.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 20 15:08:40] DEBUG[32283][C-00000002]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.147:43521
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x20a2878(SIP/50001-00000002) state from:0 to:1
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pulling 0x20a2878(SIP/50001-00000002)
    -- Channel SIP/50001-00000002 left 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x20a2878(SIP/50001-00000002) is leaving softmix technology
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: bridge_channel.c:336 ast_bridge_channel_restore_formats: Bridge is returning 0x20a2878(SIP/50001-00000002) to read format opus
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting read format path: opus -> opus
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: bridge_channel.c:346 ast_bridge_channel_restore_formats: Bridge is returning 0x20a2878(SIP/50001-00000002) to write format opus
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: channel.c:5680 set_format: Channel SIP/50001-00000002 setting write format path: opus -> opus
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: confbridge/conf_state.c:84 conf_change_state: Changing conference '350001' state from SINGLE_MARKED to EMPTY
[Feb 20 15:08:40] DEBUG[32305]: app_queue.c:2482 device_state_cb: Device 'confbridge:350001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 20 15:08:40] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: gsm -> slin
[Feb 20 15:08:40] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <CBAnn/350001-00000001;1> Playing 'confbridge-leave.gsm' (language 'en')
[Feb 20 15:08:40] DEBUG[32321][C-00000002]: app_confbridge.c:1027 destroy_conference_bridge: Destroying conference bridge '350001'

<--- SIP read from UDP:192.168.1.147:23681 --->


<------------->
[Feb 20 15:08:40] DEBUG[32283]: chan_sip.c:9893 parse_request:  Header  0 [  0]: 
[Feb 20 15:08:41] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:41] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:41] DEBUG[32323]: channel.c:3469 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 20 15:08:41] DEBUG[32323]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;1 setting write format path: slin -> slin
[Feb 20 15:08:41] DEBUG[32323]: channel.c:2728 ast_hangup: Hanging up channel 'CBAnn/350001-00000001;1'
[Feb 20 15:08:41] DEBUG[32233]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for CBAnn - 350001
[Feb 20 15:08:41] DEBUG[32233]: devicestate.c:474 do_state_change: Changing state for CBAnn/350001 - state 2 (In use)
[Feb 20 15:08:41] DEBUG[32305]: app_queue.c:2482 device_state_cb: Device 'CBAnn/350001' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: bridge.c:960 ast_bridge_destroy: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: telling all channels to leave the party
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: bridge.c:322 bridge_dissolve: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: dissolving bridge with cause 16(Normal Clearing)
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f04f4478c88(CBAnn/350001-00000001;2) state from:0 to:2
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: bridge.c:283 bridge_queue_action_nodup: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: queueing action type:13 sub:1001
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: pbx.c:4321 __ast_pbx_run: Extension 350001, priority 8 returned normally even though call was hung up
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: channel.c:2579 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/50001-00000002'
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up h@default:1
[Feb 20 15:08:41] DEBUG[32321][C-00000002]: pbx_lua.c:1480 lua_find_extension: Looking up h@demo:1
[Feb 20 15:08:41] DEBUG[32234]: cdr_radius.c:222 radius_log: Unable to create RADIUS record. CDR not recorded!
[Feb 20 15:08:41] DEBUG[32234]: res_config_sqlite.c:827 cdr_handler: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"" <50001>','50001','350001','default','SIP/50001-00000002','SIP/50002-00000003','ConfBridge','350001,default_bridge_32,default_useradmin,sample_user_menu','2017-02-20 15:08:27','2017-02-20 15:08:27','2017-02-20 15:08:39','12','12','ANSWERED','DOCUMENTATION','1487574507.6')
[Feb 20 15:08:41] DEBUG[32324]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: pulling 0x7f04f4478c88(CBAnn/350001-00000001;2)
    -- Channel CBAnn/350001-00000001;2 left 'softmix' base-bridge <a5f5d270-9cf6-415f-9eec-9e3a746f2b7e>
[Feb 20 15:08:41] DEBUG[32324]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge a5f5d270-9cf6-415f-9eec-9e3a746f2b7e: 0x7f04f4478c88(CBAnn/350001-00000001;2) is leaving softmix technology
[Feb 20 15:08:41] WARNING[32321][C-00000002]: channel.c:2268 ast_channel_destructor: Channel 'SIP/50001-00000002' may not have been hung up properly
[Feb 20 15:08:41] WARNING[32321][C-00000002]: channel.c:2268 ast_channel_destructor: Channel 'SIP/50001-00000002' may not have been hung up properly
iZ94rhgsz5zZ*CLI> *** glibc detected *** /usr/sbin/asterisk: free(): invalid pointer: 0x00007f04f8033108 ***
======= Backtrace: =========
/lib64/libc.so.6(+0x75f3e)[0x7f050e6bbf3e]
/lib64/libc.so.6(+0x78d8d)[0x7f050e6bed8d]
/usr/sbin/asterisk[0x4bd077]
/usr/sbin/asterisk[0x460c49]
/usr/sbin/asterisk(__ao2_ref_debug+0x5d)[0x460dc6]
/usr/sbin/asterisk[0x4621ab]
/usr/sbin/asterisk[0x462b17]
/usr/sbin/asterisk(__ao2_callback_debug+0x66)[0x462ccd]
/usr/sbin/asterisk(__ao2_unlink_debug+0x7c)[0x462646]
/usr/sbin/asterisk(ast_hangup+0x2c8)[0x4be489]
/usr/sbin/asterisk[0x592165]
/usr/sbin/asterisk[0x5924a8]
/usr/sbin/asterisk[0x620766]
/lib64/libpthread.so.0(+0x7aa1)[0x7f050f573aa1]
/lib64/libc.so.6(clone+0x6d)[0x7f050e72eaad]
======= Memory map: ========
00400000-00778000 r-xp 00000000 fc:01 374758                             /usr/sbin/asterisk
00978000-009bf000 rw-p 00378000 fc:01 374758                             /usr/sbin/asterisk
009bf000-009e9000 rw-p 00000000 00:00 0 
017b6000-02e65000 rw-p 00000000 00:00 0                                  [heap]
7f04b5875000-7f04b5876000 ---p 00000000 00:00 0 
7f04b5876000-7f04b58f1000 rw-p 00000000 00:00 0 
7f04b58f1000-7f04b5917000 r-xp 00000000 fc:01 369365                     /usr/lib64/libnssdbm3.so
7f04b5917000-7f04b5b17000 ---p 00026000 fc:01 369365                     /usr/lib64/libnssdbm3.so
7f04b5b17000-7f04b5b18000 r--p 00026000 fc:01 369365                     /usr/lib64/libnssdbm3.so
7f04b5b18000-7f04b5b19000 rw-p 00027000 fc:01 369365                     /usr/lib64/libnssdbm3.so
7f04b5b19000-7f04b5b3d000 r-xp 00000000 fc:01 369808                     /usr/lib64/libnsspem.so
7f04b5b3d000-7f04b5d3c000 ---p 00024000 fc:01 369808                     /usr/lib64/libnsspem.so
[Feb 20 15:08:41] DEBUG[32324]: bridge_channel.c:336 ast_bridge_channel_restore_formats: Bridge is returning 0x7f04f4478c88(CBAnn/350001-00000001;2) to read format slin
iZ94rhgsz5zZ*CLI> 3000 fc:01 369808                     /usr/lib64/libnsspem.so
7f04b5d3e000-7f04b5d3f000 rw-p 00025000 fc:01 369808                     /usr/lib64/libnsspem.so
7f04b5d3f000-7f04b5d41000 r-xp 00000000 fc:01 369813                     /usr/lib64/libnsssysinit.so
7f04b5d41000-7f04b5f40000 ---p 00002000 fc:01 369813                     /usr/lib64/libnsssysinit.so
7f04b5f40000-7f04b5f41000 r--p 00001000 fc:01 369813                     /usr/lib64/libnsssysinit.so
7f04b5f41000-7f04b5f42000 rw-p 00002000 fc:01 369813                     /usr/lib64/libnsssysinit.so
7f04b5f42000-7f04b5fb4000 r-xp 00000000 fc:01 1261575                    /lib64/libfreeblpriv3.so
7f04b5fb4000-7f04b61b4000 ---p 00072000 fc:01 1261575                    /lib64/libfreeblpriv3.so
7f04b61b4000-7f04b61b6000 r--p 00072000 fc:01 1261575                    /lib64/libfreeblpriv3.so
7f04b61b6000-7f04b61b7000 rw-p 00074000 fc:01 1261575                    /lib64/libfreeblpriv3.so
7f04b61b7000-7f04b61bb000 rw-p 00000000 00:00 0 
7f04b61bb000-7f04b61f9000 r-xp 00000000 fc:01 369367                     /usr/lib64/libsoftokn3.so
7f04b61f9000-7f04b63f8000 ---p 0003e000 fc:01 369367                     /usr/lib64/libsoftokn3.so
7f04b63f8000-7f04b63fa000 r--p 0003d000 fc:01 369367                     /usr/lib64/libsoftokn3.so
7f04b63fa000-7f04b63fb000 rw-p 0003f000 fc:01 369367                     /usr/lib64/libsoftokn3.so
7f04b63fb000-7f04b63fc000 ---p 00000000 00:00 0 
7f04b63fc000-7f04b6477000 rw-p 00000000 00:00 0 
7f04b6477000-7f04b6478000 ---p 00000000 00:00 0 
7f04b6478000-7f04b64f3000 rw-p 00000000 00:00 0 
7f04b64f3000-7f04b64f4000 ---p 00000000 00:00 0 
7f04b64f4000-7f04b656f000 rw-p 00000000 00:00 0 
7f04b656f000-7f04b6570000 ---p 00000000 00:00 0 
7f04b6570000-7f04b65eb000 rw-p 00000000 00:00 0 
7f04b65eb000-7f04b65ec000 ---p 00000000 00:00 0 
7f04b65ec000-7f04b6667000 rw-p 00000000 00:00 0 
7f04b6667000-7f04b6668000 ---p 00000000 00:00 0 
7f04b6668000-7f04b66e3000 rw-p 00000000 00:00 0 
7f04b66e3000-7f04b66e4000 ---p 00000000 00:00 0 
7f04b66e4000-7f04b675f000 rw-p 00000000 00:00 0 
7f04b675f000-7f04b6760000 ---p 00000000 00:00 0 
7f04b6760000-7f04b67db000 rw-p 00000000 00:00 0 
7f04b67db000-7f04b67dc000 ---p 00000000 00:00 0 
7f04b67dc000-7f04b6857000 rw-p 00000000 00:00 0 
7f04b6857000-7f04b6858000 ---p 00000000 00:00 0 
7f04b6858000-7f04b68d3000 rw-p 00000000 00:00 0 
7f04b68d3000-7f04b68d4000 ---p 00000000 00:00 0 
7f04b68d4000-7f04b694f000 rw-p 00000000 00:00 0 
7f04b694f000-7f04b6950000 ---p 00000000 00:00 0 
7f04b6950000-7f04b69cb000 rw-p 00000000 00:00 0 
7f04b69cb000-7f04b69cc000 ---p 00000000 00:00 0 
7f04b69cc000-7f04b6a47000 rw-p 00000000 00:00 0 
7f04b6a47000-7f04b6a48000 ---p 00000000 00:00 0 
7f04b6a48000-7f04b6ac3000 rw-p 00000000 00:00 0 
7f04b6ac3000-7f04b6ac4000 ---p 00000000 00:00 0 
7f04b6ac4000-7f04b6b3f000 rw-p 00000000 00:00 0 
7f04b6b3f000-7f04b6b40000 ---p 00000000 00:00 0 
7f04b6b40000-7f04b6bbb000 rw-p 00000000 00:00 0 
7f04b6bbb000-7f04b6bbc000 ---p 00000000 00:00 0 
7f04b6bbc000-7f04b6c37000 rw-p 00000000 00:00 0 
7f04b6c37000-7f04b6c38000 ---p 00000000 00:00 0 
7f04b6c38000-7f04b6cb3000 rw-p 00000000 00:00 0 
7f04b6cb3000-7f04b6cb4000 ---p 00000000 00:00 0 
7f04b6cb4000-7f04b6d2f000 rw-p 00000000 00:00 0 
7f04b6d2f000-7f04b6d30000 ---p 00000000 00:00 0 
7f04b6d30000-7f04b6dab000 rw-p 00000000 00:00 0 
7f04b6dab000-7f04b6dac000 ---p 00000000 00:00 0 
7f04b6dac000-7f04b6e27000 rw-p 00000000 00:00 0 
7f04b6e27000-7f04b6e28000 ---p 00000000 00:00 0 
7f04b6e28000-7f04b6ea3000 rw-p 00000000 00:00 0 
7f04b6ea3000-7f04b6ea4000 ---p 00000000 00:00 0 
7f04b6ea4000-7f04b6f1f000 rw-p 00000000 00:00 0 
7f04b6f1f000-7f04b6f20000 ---p 00000000 00:00 0 
7f04b6f20000-7f04b6f9b000 rw-p 00000000 00:00 0 
7f04b6f9b000-7f04b6f9c000 ---p 00000000 00:00 0 
7f04b6f9c000-7f04b7017000 rw-p 00000000 00:00 0 
7f04b7017000-7f04b7018000 ---p 00000000 00:00 0 
7f04b7018000-7f04b7093000 rw-p 00000000 00:00 0 
7f04b7093000-7f04b7094000 ---p 00000000 00:00 0 
7f04b7094000-7f04b710f000 rw-p 00000000 00:00 0 
7f04b710f000-7f04b7110000 ---p 00000000 00:00 0 
7f04b7110000-7f04b718b000 rw-p 00000000 00:00 0 
7f04b718b000-7f04b718c000 ---p 00000000 00:00 0 
7f04b718c000-7f04b7207000 rw-p 00000000 00:00 0 
7f04b7207000-7f04b7208000 ---p 00000000 00:00 0 
7f04b7208000-7f04b7283000 rw-p 00000000 00:00 0 
7f04b7283000-7f04b7284000 ---p 00000000 00:00 0 
7f04b7284000-7f04b72ff000 rw-p 00000000 00:00 0 
7f04b72ff000-7f04b7300000 ---p 00000000 00:00 0 
7f04b7300000-7f04b737b000 rw-p 00000000 00:00 0 
7f04b737b000-7f04b737c000 ---p 00000000 00:00 0 
7f04b737c000-7f04b73f7000 rw-p 00000000 00:00 0 
7f04b73f7000-7f04b73f8000 ---p 00000000 00:00 0 
7f04b73f8000-7f04b7473000 rw-p 00000000 00:00 0 
7f04b7473000-7f04b7474000 ---p 00000000 00:00 0 
7f04b7474000-7f04b74ef000 rw-p 00000000 00:00 0 
7f04b74ef000-7f04b74f0000 ---p 00000000 00:00 0 
7f04b74f0000-7f04b756b000 rw-p 00000000 00:00 0 
7f04b756b000-7f04b756c000 ---p 00000000 00:00 0 
7f04b756c000-7f04b75e7000 rw-p 00000000 00:00 0 
7f04b75e7000-7f04b75e8000 ---p 00000000 00:00 0 
7f04b75e8000-7f04b7663000 rw-p 00000000 00:00 0 
7f04b7663000-7f04b7664000 ---p 00000000 00:00 0 
7f04b7664000-7f04b76df000 rw-p 00000000 00:00 0 
7f04b76df000-7f04b76e0000 ---p 00000000 00:00 0 
7f04b76e0000-7f04b775b000 rw-p 00000000 00:00 0 
7f04b775b000-7f04b775c000 ---p 00000000 00:00 0 
7f04b775c000-7f04b77d7000 rw-p 00000000 00:00 0 
7f04b77d7000-7f04b77d8000 ---p 00000000 00:00 0 
7f04b77d8000-7f04b81d8000 rw-p 00000000 00:00 0 
7f04b81d8000-7f04b81d9000 ---p 00000000 00:00 0 
7f04b81d9000-7f04b8254000 rw-p 00000000 00:00 0 
7f04b8254000-7f04b8255000 ---p 00000000 00:00 0 
7f04b8255000-7f04b82d0000 rw-p 00000000 00:00 0 
7f04b82d0000-7f04b82d1000 ---p 00000000 00:00 0 
7f04b82d1000-7f04b834c000 rw-p 00000000 00:00 0 
7f04b834c000-7f04b8350000 r-xp 00000000 fc:01 394550                     /usr/lib/asterisk/modules/app_page.so
7f04b8350000-7f04b854f000 ---p 00004000 fc:01 394550                     /usr/lib/asterisk/modules/app_page.so
7f04b854f000-7f04b8550000 rw-p 00003000 fc:01 394550                     /usr/lib/asterisk/modules/app_page.so
7f04b8550000-7f04b8553000 r-xp 00000000 fc:01 394537                     /usr/lib/asterisk/modules/app_forkcdr.so
7f04b8553000-7f04b8752000 ---p 00003000 fc:01 394537                     /usr/lib/asterisk/modules/app_forkcdr.so
7f04b8752000-7f04b8753000 rw-p 00002000 fc:01 394537                     /usr/lib/asterisk/modules/app_forkcdr.so
7f04b8753000-7f04b875b000 r-xp 00000000 fc:01 394761                     /usr/lib/asterisk/modules/res_pjsip_mwi.so
7f04b875b000-7f04b895b000 ---p 00008000 fc:01 394761                     /usr/lib/asterisk/modules/res_pjsip_mwi.so
[Feb 20 15:08:41] DEBUG[32324]: channel.c:5680 set_format: Channel CBAnn/350001-00000001;2 setting read format path: slin -> slin
[Feb 20 15:08:41] DEBUG[32324]: bridge_channel.c:346 ast_bridge_channel_restore_formats: Bridge is returning 0x7f04f4478c88(CBAnn/350001-00000001;2) to write format slin
iZ94rhgsz5zZ*CLI> 
Disconnected from Asterisk server
Asterisk cleanly ending (0).
Executing last minute cleanups
[root@iZ94rhgsz5zZ 13.14.0]#