[Aug  9 22:17:16] VERBOSE[2642] config.c:   == Parsing '/etc/asterisk/logger.conf': [Aug  9 22:17:16] DEBUG[2642] config.c: Parsing /etc/asterisk/logger.conf
[Aug  9 22:17:16] VERBOSE[2642] config.c:   == Found
[Aug  9 22:17:16] VERBOSE[2642] logger.c:  Asterisk Event Logger restarted
[Aug  9 22:17:16] VERBOSE[2642] logger.c:  Asterisk Queue Logger restarted
[Aug  9 22:17:21] DEBUG[2533] acl.c: Found IP address for this socket
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 4.3.2.4:5060
[Aug  9 22:17:21] VERBOSE[2533] netsock.c:   == Using SIP RTP CoS mark 5
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Setting NAT on RTP to Off
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Allocating new SIP dialog for NzE0MmYxYzM0YzZjZTkxNTBhOGVhMzRiYWUwYTM5ZDg. - INVITE (With RTP)
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Setting NAT on RTP to On
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Stopping retransmission on 'NzE0MmYxYzM0YzZjZTkxNTBhOGVhMzRiYWUwYTM5ZDg.' of Response 1: Match Found
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Setting NAT on RTP to On
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing session-level SDP o=- 9 2 IN IP4 4.3.2.3... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing session-level SDP s=CounterPath eyeBeam 1.5... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing session-level SDP c=IN IP4 4.3.2.3... OK.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=yes... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=alt:1 3 : qLRjq4Rx /B7BKlhW 4.3.2.3 37946... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=alt:2 2 : sj8PzdKn Kkh2/pQS 10.211.55.2 37946... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=alt:3 1 : 5cyoJQ6E gyT4/t2S 10.37.129.2 37946... UNSUPPORTED.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Checking SIP call limits for device 110
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Updating call counter for incoming call
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) 
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: This channel will not be able to handle video.
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: build_route: Contact hop: <sip:110@4.3.2.3:46384>
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: SIP/110-00000004: New call is still down.... Trying... 
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: No provider found, checking channel drivers for SIP - 110
[Aug  9 22:17:21] DEBUG[2418] chan_sip.c: Checking device state for peer 110
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: Changing state for SIP/110 - state 1 (Not in use)
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: device 'SIP/110' state '1'
[Aug  9 22:17:21] DEBUG[2647] pbx.c: Launching 'AGI'
[Aug  9 22:17:21] VERBOSE[2647] pbx.c:     -- Executing [1234@default:1] AGI("SIP/110-00000004", "agi://4.3.2.3:9090") in new stack
[Aug  9 22:17:21] DEBUG[2647] res_agi.c: Wow, connected!
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: No provider found, checking channel drivers for SIP - 110
[Aug  9 22:17:21] DEBUG[2418] chan_sip.c: Checking device state for peer 110
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: Changing state for SIP/110 - state 1 (Not in use)
[Aug  9 22:17:21] DEBUG[2418] devicestate.c: device 'SIP/110' state '1'
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: SIP answering channel: SIP/110-00000004
[Aug  9 22:17:21] DEBUG[2647] rtp.c: Setting the marker bit due to a source update
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: Setting framing from config on incoming call
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: -- Done with adding codecs to SDP
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Aug  9 22:17:21] DEBUG[2647] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:17:21] DEBUG[2647] rtp.c: Got RTCP report of 132 bytes
[Aug  9 22:17:21] VERBOSE[2647] res_agi.c:     -- AGI Script Executing Application: (Playback) Options: (beep&beep)
[Aug  9 22:17:21] DEBUG[2647] rtp.c: Ooh, format changed from unknown to ulaw
[Aug  9 22:17:21] DEBUG[2647] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Aug  9 22:17:21] VERBOSE[2647] file.c:     -- <SIP/110-00000004> Playing 'beep.ulaw' (language 'en')
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Aug  9 22:17:21] DEBUG[2533] chan_sip.c: Stopping retransmission on 'NzE0MmYxYzM0YzZjZTkxNTBhOGVhMzRiYWUwYTM5ZDg.' of Response 2: Match Found
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (182 requested / 182 actual) timer ticks per second
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:21] DEBUG[2647] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Aug  9 22:17:21] VERBOSE[2647] file.c:     -- <SIP/110-00000004> Playing 'beep.ulaw' (language 'en')
[Aug  9 22:17:22] DEBUG[2647] channel.c: Scheduling timer at (182 requested / 182 actual) timer ticks per second
[Aug  9 22:17:22] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:22] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:22] DEBUG[2647] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug  9 22:17:24] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:28] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:31] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:35] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:38] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:42] DEBUG[2647] rtp.c: Got RTCP report of 176 bytes
[Aug  9 22:17:43] DEBUG[2642] channel.c: Soft-Hanging up channel 'SIP/110-00000004'
[Aug  9 22:17:43] DEBUG[2647] res_agi.c: SIP/110-00000004 hungup
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Allocating new SIP dialog for 32c1bc1a33981c544eb4fe0577960f47@127.0.0.1 - OPTIONS (No RTP)
[Aug  9 22:17:57] DEBUG[2533] acl.c: Found IP address for this socket
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 4.3.2.4:5060
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Initializing initreq for method OPTIONS - callid 68c74e3476a40a933747a36739951fe5@4.3.2.4
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Stopping retransmission on '68c74e3476a40a933747a36739951fe5@4.3.2.4' of Request 102: Match Found
[Aug  9 22:17:57] DEBUG[2533] chan_sip.c: Destroying SIP dialog 68c74e3476a40a933747a36739951fe5@4.3.2.4
[Aug  9 22:18:00] VERBOSE[2642] asterisk.c:     -- Remote UNIX connection disconnected
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Allocating new SIP dialog for 01a5366836828472641a14636969696d@127.0.0.1 - OPTIONS (No RTP)
[Aug  9 22:18:57] DEBUG[2533] acl.c: Found IP address for this socket
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 4.3.2.4:5060
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Initializing initreq for method OPTIONS - callid 663b71770641805a4482784a6a37c4e6@4.3.2.4
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Stopping retransmission on '663b71770641805a4482784a6a37c4e6@4.3.2.4' of Request 102: Match Found
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Destroying SIP dialog 663b71770641805a4482784a6a37c4e6@4.3.2.4
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Setting SIP_ALREADYGONE on dialog NzE0MmYxYzM0YzZjZTkxNTBhOGVhMzRiYWUwYTM5ZDg.
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Received bye, issuing owner hangup
[Aug  9 22:18:57] DEBUG[2533] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Allocating new SIP dialog for 6bb6b96362c17b514f30ce7427769174@127.0.0.1 - OPTIONS (No RTP)
[Aug  9 22:19:57] DEBUG[2533] acl.c: Found IP address for this socket
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 4.3.2.4:5060
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Initializing initreq for method OPTIONS - callid 6ddb65dc4a8247f71a680fa9014fb0df@4.3.2.4
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Stopping retransmission on '6ddb65dc4a8247f71a680fa9014fb0df@4.3.2.4' of Request 102: Match Found
[Aug  9 22:19:57] DEBUG[2533] chan_sip.c: Destroying SIP dialog 6ddb65dc4a8247f71a680fa9014fb0df@4.3.2.4
[Aug  9 22:19:58] DEBUG[2533] acl.c: Found IP address for this socket
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 4.3.2.4:5060
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: Allocating new SIP dialog for YWIwOTg3Mjg4ODgzMGFjYmY2MzE5Mjk4NjlkNWFhYTc. - SUBSCRIBE (No RTP)
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: build_route: Contact hop: <sip:110@4.3.2.3:46384>
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: build_route: Retaining previous route: <sip:110@4.3.2.3:46384>
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 4.3.2.3:46384
[Aug  9 22:19:58] NOTICE[2533] chan_sip.c: Received SIP subscribe for peer without mailbox: 110
[Aug  9 22:19:58] DEBUG[2533] chan_sip.c: Destroying SIP dialog YWIwOTg3Mjg4ODgzMGFjYmY2MzE5Mjk4NjlkNWFhYTc.