[Dec  7 14:15:58] DEBUG[1963] chan_sip.c: ** SIP timers: Rescheduling retransmission 8 to 4000 ms (t1 500 ms (Retrans id #11)) 
[Dec  7 14:15:58] DEBUG[1963] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 172.20.31.142:52884
[Dec  7 14:15:59] DEBUG[1975] http.c: HTTP Request URI is /ws 
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [httpstatus] len 0
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [phoneprov] len 10
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [amanager] len 9
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [arawman] len 8
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [manager] len 7
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [rawman] len 7
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [static] len 6
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [amxml] len 6
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [mxml] len 5
[Dec  7 14:15:59] DEBUG[1975] http.c: match request [ws] with handler [ws] len 4
[Dec  7 14:15:59] VERBOSE[1975] res_http_websocket.c:   == WebSocket connection from '172.20.31.142:52931' for protocol 'sip' accepted using version '13'
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: = Looking for  Call ID: ac456nf99tacerk9 (Checking From) --From tag 4a6a9nuso4 --To-tag   
[Dec  7 14:15:59] DEBUG[1975] acl.c: For destination '172.20.31.142', our source address is '172.20.31.134'.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Setting SIP_TRANSPORT_WS with address 172.20.31.134:5060
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Allocating new SIP dialog for ac456nf99tacerk9 - REGISTER (No RTP)
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '88.237.167.8' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '88.237.167.8' and port ''.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: NAT detected for 88.237.167.8:5060 / 172.20.31.142:52931
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 172.20.31.142:52931
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: = Looking for  Call ID: ac456nf99tacerk9 (Checking From) --From tag 4a6a9nuso4 --To-tag   
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '88.237.167.8' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '88.237.167.8' and port ''.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: NAT detected for 88.237.167.8:5060 / 172.20.31.142:52931
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:15:59] DEBUG[1975] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: peer '1236' has contacted us over WS even though we prefer UDP.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Store REGISTER's src-IP:port for call routing.
[Dec  7 14:15:59] VERBOSE[1975] chan_sip.c:     -- Registered SIP '1236' at 172.20.31.142:52931
[Dec  7 14:15:59] VERBOSE[1975] chan_sip.c:        > Saved useragent "JsSIP 0.2.1" for peer 1236
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 172.20.31.142:52931
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Allocating new SIP dialog for 22745bf91f0e54eb60b03d754a7e678e@127.0.1.1:5060 - NOTIFY (No RTP)
[Dec  7 14:15:59] DEBUG[1975] acl.c: For destination '172.20.31.142', our source address is '172.20.31.134'.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Setting SIP_TRANSPORT_WS with address 172.20.31.134:5060
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Initializing initreq for method NOTIFY - callid 6ef2f40e356c299f2bb6d4a12eba471d@172.20.31.134:5060
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: Trying to put 'NOTIFY sip:' onto WS socket destined for 172.20.31.142:52931
[Dec  7 14:15:59] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1236
[Dec  7 14:15:59] DEBUG[1937] chan_sip.c: Checking device state for peer 1236
[Dec  7 14:15:59] DEBUG[1937] devicestate.c: Changing state for SIP/1236 - state 1 (Not in use)
[Dec  7 14:15:59] DEBUG[1937] devicestate.c: device 'SIP/1236' state '1'
[Dec  7 14:15:59] DEBUG[1973] app_queue.c: Device 'SIP/1236' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Dec  7 14:15:59] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 6ef2f40e356c299f2bb6d4a12eba471d@172.20.31.134:5060 (Checking To) --From tag as1e6cc6d1 --To-tag y3sibewa7w  
[Dec  7 14:16:02] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 8e389574-a3de7e6a@172.20.31.166 (Checking From) --From tag 46178f1a65a85f0ao0 --To-tag   
[Dec  7 14:16:02] DEBUG[1963] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
[Dec  7 14:16:02] DEBUG[1963] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.20.31.166:5060
[Dec  7 14:16:02] DEBUG[1963] chan_sip.c: ** SIP timers: Rescheduling retransmission 9 to 4000 ms (t1 500 ms (Retrans id #11)) 
[Dec  7 14:16:02] DEBUG[1963] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 172.20.31.142:52884
[Dec  7 14:16:06] DEBUG[1963] chan_sip.c: ** SIP timers: Rescheduling retransmission 10 to 4000 ms (t1 500 ms (Retrans id #11)) 
[Dec  7 14:16:06] DEBUG[1963] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 172.20.31.142:52884
[Dec  7 14:16:09] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag   
[Dec  7 14:16:09] DEBUG[1963] logger.c: CALL_ID [C-00000000] created by thread.
[Dec  7 14:16:09] DEBUG[1963] acl.c: For destination '172.20.31.145', our source address is '172.20.31.134'.
[Dec  7 14:16:09] DEBUG[1963] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.20.31.134:5060
[Dec  7 14:16:09] DEBUG[1963] chan_sip.c: Allocating new SIP dialog for 7408f050-f3a08d50@172.20.31.145 - INVITE (No RTP)
[Dec  7 14:16:09] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec  7 14:16:09] DEBUG[1963][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: x-sipura"
[Dec  7 14:16:09] DEBUG[1963][C-00000000] sip/reqresp_parser.c: Found SIP option: -x-sipura-
[Dec  7 14:16:09] DEBUG[1963][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: x-sipura
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.145:5061' into...
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.145' and port '5061'.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:09] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:09] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag as274bc012  
[Dec  7 14:16:09] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Dec  7 14:16:09] DEBUG[1963][C-00000000] chan_sip.c: Stopping retransmission on '7408f050-f3a08d50@172.20.31.145' of Response 101: Match Found
[Dec  7 14:16:09] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:09] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag   
[Dec  7 14:16:09] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:09] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:09] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:09] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.145:5061' into...
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.145' and port '5061'.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:09] DEBUG[1963][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fffe402ffb8'
[Dec  7 14:16:09] DEBUG[1963][C-00000000] res_rtp_asterisk.c: Allocated port 19812 for RTP instance '0x7fffe402ffb8'
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:09] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:10] DEBUG[1963][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:10] DEBUG[1963][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:10] DEBUG[1963][C-00000000] rtp_engine.c: RTP instance '0x7fffe402ffb8' is setup and ready to go
[Dec  7 14:16:10] DEBUG[1963][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fffe402ffb8'
[Dec  7 14:16:10] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:10] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:11] VERBOSE[1963][C-00000000] netsock2.c:   == Using SIP RTP CoS mark 5
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Setting NAT on RTP to Off
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing session-level SDP o=- 7343841 7343841 IN IP4 172.20.31.145... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.145' into...
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.145' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 172.20.31.145... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 2 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 4 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 18 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 96 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 97 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 98 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 100 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Setting payload 101 based on m type on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Unsetting payload 96 on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Unsetting payload 97 on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Unsetting payload 98 on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Unsetting payload 100 on 0x7fffbb4cff60
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 NSE/8000... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fffe402ffb8'
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 0 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 2 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 4 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 8 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 18 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] rtp_engine.c: Copying payload 101 from 0x7fffbb4cff60 to 0x7fffe4030180
[Dec  7 14:16:11] DEBUG[1963][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fffe402ffb8'
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw)
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Checking SIP call limits for device 1235
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Updating call counter for incoming call
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1235
[Dec  7 14:16:11] DEBUG[1937] chan_sip.c: Checking device state for peer 1235
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: Changing state for SIP/1235 - state 2 (In use)
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: device 'SIP/1235' state '2'
[Dec  7 14:16:11] DEBUG[1973] app_queue.c: Device 'SIP/1235' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] format_pref.c: Could not find preferred codec - Going for the best codec
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: *** Our native formats are (ulaw) 
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw|alaw) 
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) 
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: This channel will not be able to handle video.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: build_route: Contact hop: Sipura2 <sip:1235@172.20.31.145:5061>
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: SIP/1235-00000000: New call is still down.... Trying... 
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1235
[Dec  7 14:16:11] DEBUG[1937] chan_sip.c: Checking device state for peer 1235
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: Changing state for SIP/1235 - state 2 (In use)
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: device 'SIP/1235' state '2'
[Dec  7 14:16:11] DEBUG[1973] app_queue.c: Device 'SIP/1235' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:11] DEBUG[1963] chan_sip.c: Auto destroying SIP dialog '25a1264e3326600253a20c2f08dab43f@172.20.31.134:5060'
[Dec  7 14:16:11] DEBUG[1963] chan_sip.c: Destroying SIP dialog 25a1264e3326600253a20c2f08dab43f@172.20.31.134:5060
[Dec  7 14:16:11] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag   
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Ignoring SIP message because of retransmit (INVITE Seqno 102, ours 102)
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:11] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:11] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag   
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1963] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Ignoring SIP message because of retransmit (INVITE Seqno 102, ours 102)
[Dec  7 14:16:11] DEBUG[1963][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:11] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Launching 'Macro'
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] pbx.c:     -- Executing [1236@demo-ctx:1] Macro("SIP/1235-00000000", "stdexten,1236,SIP/1236") in new stack
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Result of 'ARG1' is '1236'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Function result is '0'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Launching 'GotoIf'
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] pbx.c:     -- Executing [s@macro-stdexten:1] GotoIf("SIP/1235-00000000", "$~np~["0" != "0"]~/np~?3") in new stack
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] pbx.c:     -- Goto (macro-stdexten,s,3)
[Dec  7 14:16:11] DEBUG[1976][C-00000000] app_macro.c: Executed application: GotoIf
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Launching 'SendText'
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] pbx.c:     -- Executing [s@macro-stdexten:3] SendText("SIP/1235-00000000", "You have voicemail messages") in new stack
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Trying to send MESSAGE to device that does not support it.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] app_macro.c: Executed application: SendText
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Result of 'ARG2' is 'SIP/1236'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] pbx.c: Launching 'Dial'
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] pbx.c:     -- Executing [s@macro-stdexten:4] Dial("SIP/1235-00000000", "SIP/1236,10,tTr") in new stack
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Allocating new SIP dialog for 3d94471242599bec05dc114307412409@127.0.1.1:5060 - INVITE (No RTP)
[Dec  7 14:16:11] DEBUG[1976][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Allocated port 15612 for RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] rtp_engine.c: RTP instance '0x7ffff0021fb8' is setup and ready to go
[Dec  7 14:16:11] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.134' into...
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.134' and port ''.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:11] DEBUG[1976][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] netsock2.c:   == Using SIP RTP CoS mark 5
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Setting NAT on RTP to On
[Dec  7 14:16:11] DEBUG[1976][C-00000000] acl.c: For destination '172.20.31.142', our source address is '172.20.31.134'.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Setting SIP_TRANSPORT_WS with address 172.20.31.134:5060
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: *** Our native formats are (ulaw) 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: *** Our capabilities are (gsm|ulaw|alaw|ilbc) 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: This channel will not be able to handle video.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel_internal_api.c: Channel Call ID changing from [C-00000000] to [C-00000000]
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable DIALEDTIME.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable ANSWEREDTIME.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable DIALEDPEERNAME.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable DIALEDPEERNUMBER.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable DIALSTATUS.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable MACRO_DEPTH.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable SENDTEXTSTATUS.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable ARG2.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable ARG1.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable MACRO_PRIORITY.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable MACRO_CONTEXT.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable MACRO_EXTEN.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable SIPCALLID.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable SIPDOMAIN.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] channel.c: Not copying variable SIPURI.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Outgoing Call for 1236
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Updating call counter for outgoing call
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1236
[Dec  7 14:16:11] DEBUG[1937] chan_sip.c: Checking device state for peer 1236
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: Changing state for SIP/1236 - state 6 (Ringing)
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: device 'SIP/1236' state '6'
[Dec  7 14:16:11] DEBUG[1973] app_queue.c: Device 'SIP/1236' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: ** Our capability: (gsm|ulaw|alaw|ilbc) Video flag: False Text flag: False
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: ** Our prefcodec: (ulaw) 
[Dec  7 14:16:11] DEBUG[1976][C-00000000] sip/sdp_crypto.c: local_key64 14t4nNkT3tJ+u7RrxFwA9EBXjIWSONwQztmZly1f len 40
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: -- Done with adding codecs to SDP
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (gsm|ulaw|alaw|ilbc)
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto WS socket destined for 172.20.31.142:52931
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] app_dial.c:     -- Called SIP/1236
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:11] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag   
[Dec  7 14:16:11] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:11] DEBUG[1975][C-00000000] chan_sip.c: SIP response 100 to standard invite
[Dec  7 14:16:11] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:11] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag e6wmkzcgie  
[Dec  7 14:16:11] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:11] DEBUG[1975][C-00000000] chan_sip.c: SIP response 180 to standard invite
[Dec  7 14:16:11] DEBUG[1975][C-00000000] chan_sip.c: build_route: Contact hop: <sip:1236@88.237.167.8;transport=ws>
[Dec  7 14:16:11] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1236
[Dec  7 14:16:11] DEBUG[1937] chan_sip.c: Checking device state for peer 1236
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: Changing state for SIP/1236 - state 6 (Ringing)
[Dec  7 14:16:11] DEBUG[1937] devicestate.c: device 'SIP/1236' state '6'
[Dec  7 14:16:11] DEBUG[1973] app_queue.c: Device 'SIP/1236' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Dec  7 14:16:11] VERBOSE[1976][C-00000000] app_dial.c:     -- SIP/1236-00000001 is ringing
[Dec  7 14:16:11] DEBUG[1976][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:12] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag e6wmkzcgie  
[Dec  7 14:16:12] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:12] DEBUG[1975][C-00000000] chan_sip.c: SIP response 180 to standard invite
[Dec  7 14:16:12] DEBUG[1975][C-00000000] chan_sip.c: build_route: Contact hop: <sip:1236@88.237.167.8;transport=ws>
[Dec  7 14:16:12] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:12] VERBOSE[1976][C-00000000] app_dial.c:     -- SIP/1236-00000001 is ringing
[Dec  7 14:16:14] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag e6wmkzcgie  
[Dec  7 14:16:14] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:14] DEBUG[1975][C-00000000] chan_sip.c: SIP response 180 to standard invite
[Dec  7 14:16:14] DEBUG[1975][C-00000000] chan_sip.c: build_route: Contact hop: <sip:1236@88.237.167.8;transport=ws>
[Dec  7 14:16:14] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:14] VERBOSE[1976][C-00000000] app_dial.c:     -- SIP/1236-00000001 is ringing
[Dec  7 14:16:17] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 8e389574-a3de7e6a@172.20.31.166 (Checking From) --From tag 46178f1a65a85f0ao0 --To-tag   
[Dec  7 14:16:17] DEBUG[1963] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY
[Dec  7 14:16:17] DEBUG[1963] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.20.31.166:5060
[Dec  7 14:16:18] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag e6wmkzcgie  
[Dec  7 14:16:18] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:18] DEBUG[1975][C-00000000] chan_sip.c: SIP response 180 to standard invite
[Dec  7 14:16:18] DEBUG[1975][C-00000000] chan_sip.c: build_route: Contact hop: <sip:1236@88.237.167.8;transport=ws>
[Dec  7 14:16:18] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:18] VERBOSE[1976][C-00000000] app_dial.c:     -- SIP/1236-00000001 is ringing
[Dec  7 14:16:20] DEBUG[1975] chan_sip.c: = Looking for  Call ID: 0eba7230414fb4b532cf1ced7d70d73c@172.20.31.134:5060 (Checking To) --From tag as133217bd --To-tag e6wmkzcgie  
[Dec  7 14:16:20] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: SIP response 200 to standard invite
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing session-level SDP o=- 2454507864 2 IN IP4 127.0.0.1... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7fffbaefda20
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7fffbaefda20
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Setting payload 101 based on m type on 0x7fffbaefda20
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 186.215.138.93... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:1712 IN IP4 186.215.138.93... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '0' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '0' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1710441505 1 udp 2113937151 172.20.31.142 51204 typ host generation 0... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '0' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '0' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1710441505 1 udp 1677729535 186.215.138.93 1741 typ srflx generation 0... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '0' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '0' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1710441505 2 udp 2113937150 172.20.31.142 63793 typ host generation 0... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '186.215.138.93' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '186.215.138.93' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: Splitting '0' into...
[Dec  7 14:16:20] DEBUG[1975][C-00000000] netsock2.c: ...host '0' and port ''.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1710441505 2 udp 1677729534 186.215.138.93 1712 typ srflx generation 0... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:tms90HV2q2a9LB7r... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:lHK+G68dd51PHib3+QG6+XxR... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] res_srtp.c: Adding new policy for SSRC 2112492283
[Dec  7 14:16:20] DEBUG[1975][C-00000000] sip/sdp_crypto.c: SRTP policy activated
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:DaLRmGqDa6vWNq2V1nA2wwXKXTwakKhAG/qDsTef... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:416426215 cname:lBKsnz+poAfwn1Lt... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:416426215 msid:N7Wy1oGeCd9EQyl4GmaZMjCmAynRZBD1nha5 a0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:416426215 mslabel:N7Wy1oGeCd9EQyl4GmaZMjCmAynRZBD1nha5... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:416426215 label:N7Wy1oGeCd9EQyl4GmaZMjCmAynRZBD1nha5a0... UNSUPPORTED OR FAILED.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Copying payload 0 from 0x7fffbaefda20 to 0x7ffff0022180
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Copying payload 8 from 0x7fffbaefda20 to 0x7ffff0022180
[Dec  7 14:16:20] DEBUG[1975][C-00000000] rtp_engine.c: Copying payload 101 from 0x7fffbaefda20 to 0x7ffff0022180
[Dec  7 14:16:20] DEBUG[1975][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw)
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: We have an owner, now see if we need to change this call
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Updating call counter for outgoing call
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1236
[Dec  7 14:16:20] DEBUG[1937] chan_sip.c: Checking device state for peer 1236
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: Changing state for SIP/1236 - state 2 (In use)
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: device 'SIP/1236' state '2'
[Dec  7 14:16:20] DEBUG[1973] app_queue.c: Device 'SIP/1236' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: build_route: Contact hop: <sip:1236@88.237.167.8;transport=ws>
[Dec  7 14:16:20] DEBUG[1975][C-00000000] chan_sip.c: Trying to put 'ACK sip:123' onto WS socket destined for 172.20.31.142:52931
[Dec  7 14:16:20] VERBOSE[1976][C-00000000] app_dial.c:     -- SIP/1236-00000001 answered SIP/1235-00000000
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1236
[Dec  7 14:16:20] DEBUG[1937] chan_sip.c: Checking device state for peer 1236
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: Changing state for SIP/1236 - state 2 (In use)
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: device 'SIP/1236' state '2'
[Dec  7 14:16:20] DEBUG[1973] app_queue.c: Device 'SIP/1236' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: No provider found, checking channel drivers for SIP - 1235
[Dec  7 14:16:20] DEBUG[1937] chan_sip.c: Checking device state for peer 1235
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: Changing state for SIP/1235 - state 2 (In use)
[Dec  7 14:16:20] DEBUG[1937] devicestate.c: device 'SIP/1235' state '2'
[Dec  7 14:16:20] DEBUG[1973] app_queue.c: Device 'SIP/1235' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: SIP answering channel: SIP/1235-00000000
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: Setting framing from config on incoming call
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) 
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: -- Done with adding codecs to SDP
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw)
[Dec  7 14:16:20] DEBUG[1976][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.20.31.145:5061
[Dec  7 14:16:20] DEBUG[1976][C-00000000] features.c: bridge answer set, chan answer set
[Dec  7 14:16:20] DEBUG[1976][C-00000000] features.c: Removing dialed interfaces datastore on SIP/1236-00000001 since we're bridging
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Dec  7 14:16:20] DEBUG[1975][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:20] DEBUG[1963] chan_sip.c: = Looking for  Call ID: 7408f050-f3a08d50@172.20.31.145 (Checking From) --From tag 5d259450aa8c3950o1 --To-tag as3b9bafe4  
[Dec  7 14:16:20] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[Dec  7 14:16:20] DEBUG[1963][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Dec  7 14:16:20] DEBUG[1963][C-00000000] chan_sip.c: Stopping retransmission on '7408f050-f3a08d50@172.20.31.145' of Response 102: Match Found
[Dec  7 14:16:20] DEBUG[1963][C-00000000] logger.c: CALL_ID [C-00000000] being removed from thread.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- start learning mode pass with addr = 172.20.31.145:16460
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- probation = 4, seq = 1360
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- Condition for learning hasn't exited, so reject the frame.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- start learning mode pass with addr = 172.20.31.145:16460
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- probation = 3, seq = 1361
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- Condition for learning hasn't exited, so reject the frame.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- start learning mode pass with addr = 172.20.31.145:16460
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- probation = 2, seq = 1362
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- Condition for learning hasn't exited, so reject the frame.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- start learning mode pass with addr = 172.20.31.145:16460
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- probation = 1, seq = 1363
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: 0x7fffe4036920 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 172.20.31.145:16460
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7ffff0021fb8'
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] res_rtp_asterisk.c: Got RTCP report of 56 bytes
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:20] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: Splitting '172.20.31.142' into...
[Dec  7 14:16:21] DEBUG[1976][C-00000000] netsock2.c: ...host '172.20.31.142' and port ''.