[Jun  2 17:17:45] VERBOSE[13679] logger.c: Asterisk Event Logger restarted
[Jun  2 17:17:45] VERBOSE[13679] logger.c: Asterisk Queue Logger restarted
[Jun  2 17:17:45] VERBOSE[13679] logger.c:     -- Remote UNIX connection disconnected
[Jun  2 17:17:49] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:17:49] DEBUG[13528] chan_sip.c: = Found Their Call ID: 685bdd1b6ac8b02e6b8298f436008c1c@192.168.222.35 Their Tag  Our tag: as3d4af2fe
[Jun  2 17:17:49] DEBUG[13528] chan_sip.c: Stopping retransmission on '685bdd1b6ac8b02e6b8298f436008c1c@192.168.222.35' of Request 102: Match Found
[Jun  2 17:17:49] VERBOSE[13528] logger.c: Really destroying SIP dialog '685bdd1b6ac8b02e6b8298f436008c1c@192.168.222.35' Method: OPTIONS
[Jun  2 17:17:54] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:17:54] DEBUG[13528] chan_sip.c: = Found Their Call ID: 7493e4131a5974a50ae7412e394c76aa@192.168.222.35 Their Tag  Our tag: as1a640751
[Jun  2 17:17:54] DEBUG[13528] chan_sip.c: Stopping retransmission on '7493e4131a5974a50ae7412e394c76aa@192.168.222.35' of Request 102: Match Found
[Jun  2 17:17:54] VERBOSE[13528] logger.c: Really destroying SIP dialog '7493e4131a5974a50ae7412e394c76aa@192.168.222.35' Method: OPTIONS
[Jun  2 17:17:57] VERBOSE[13516] logger.c:     -- Remote UNIX connection
[Jun  2 17:17:57] DEBUG[13539] chan_iax2.c: ip callno count decremented to 0 for 192.168.222.3
[Jun  2 17:17:57] DEBUG[13535] chan_iax2.c: ip callno count incremented to 1 for 192.168.222.3
[Jun  2 17:17:57] DEBUG[13536] chan_iax2.c: schedule decrement of callno used for 192.168.222.3 in 60 seconds
[Jun  2 17:17:57] DEBUG[13536] chan_iax2.c: Peer TRUNK_TEST_VIRT: got pong, lastms 14, historicms 14, maxms 2000
[Jun  2 17:17:57] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:17:57] DEBUG[13528] chan_sip.c: = Found Their Call ID: 62a077636ab3f89d56bcab8841c6268c@192.168.222.35 Their Tag  Our tag: as424f8d17
[Jun  2 17:17:57] DEBUG[13528] chan_sip.c: Stopping retransmission on '62a077636ab3f89d56bcab8841c6268c@192.168.222.35' of Request 102: Match Found
[Jun  2 17:17:57] VERBOSE[13528] logger.c: Really destroying SIP dialog '62a077636ab3f89d56bcab8841c6268c@192.168.222.35' Method: OPTIONS
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. - INVITE (With RTP)
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: = Found Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as5dfb6358
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Stopping retransmission on 'MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE.' of Response 1: Match Found
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: = Found Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as5dfb6358
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing session-level SDP o=Z 0 0 IN IP4 192.168.222.45... UNSUPPORTED.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing session-level SDP s=Z... UNSUPPORTED.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.222.45... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: T38 state changed to 0 on channel <none>
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: We're settling with these formats: 0x2 (gsm)
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Checking SIP call limits for device 100
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Updating call counter for incoming call
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: *** Our native formats are 0x2 (gsm) 
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: *** Joint capabilities are 0x2 (gsm) 
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: *** Our capabilities are 0x2 (gsm) 
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) 
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: This channel will not be able to handle video.
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: build_route: Contact hop: <sip:100@192.168.222.45:5061;transport=UDP>
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: SIP/100-00000008: New call is still down.... Trying... 
[Jun  2 17:18:02] DEBUG[13528] devicestate.c: Notification of state change to be queued on device/channel SIP/100
[Jun  2 17:18:02] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 100
[Jun  2 17:18:02] DEBUG[13686] pbx.c: Launching 'AgentLogin'
[Jun  2 17:18:02] VERBOSE[13686] logger.c:     -- Executing [7700@default:1] AgentLogin("SIP/100-00000008", "") in new stack
[Jun  2 17:18:02] DEBUG[13521] chan_sip.c: Checking device state for peer 100
[Jun  2 17:18:02] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel SIP/100
[Jun  2 17:18:02] DEBUG[13521] devicestate.c: Changing state for SIP/100 - state 1 (Not in use)
[Jun  2 17:18:02] DEBUG[13524] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: SIP answering channel: SIP/100-00000008
[Jun  2 17:18:02] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 100
[Jun  2 17:18:02] DEBUG[13686] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:02] DEBUG[13521] chan_sip.c: Checking device state for peer 100
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: Setting framing from config on incoming call
[Jun  2 17:18:02] DEBUG[13521] devicestate.c: Changing state for SIP/100 - state 1 (Not in use)
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: True
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: -- Done with adding codecs to SDP
[Jun  2 17:18:02] DEBUG[13686] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm)
[Jun  2 17:18:02] DEBUG[13524] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:02] DEBUG[13686] rtp.c: Ooh, format changed from unknown to gsm
[Jun  2 17:18:02] DEBUG[13686] rtp.c: Created smoother: format: 2 ms: 20 len: 33
[Jun  2 17:18:02] VERBOSE[13686] logger.c:     -- <SIP/100-00000008> Playing 'agent-user' (language 'es')
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: = Found Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:02] DEBUG[13528] chan_sip.c: Stopping retransmission on 'MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE.' of Response 2: Match Found
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF begin ignored '1' on SIP/100-00000008
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:04] DEBUG[13686] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF begin '0' received on SIP/100-00000008
[Jun  2 17:18:04] DTMF[13686] channel.c: DTMF begin ignored '0' on SIP/100-00000008
[Jun  2 17:18:04] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF end '0' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF end passthrough '0' on SIP/100-00000008
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF begin '0' received on SIP/100-00000008
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF begin ignored '0' on SIP/100-00000008
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF end '0' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:05] DTMF[13686] channel.c: DTMF end passthrough '0' on SIP/100-00000008
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:18:05] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF begin ignored '1' on SIP/100-00000008
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF begin '#' received on SIP/100-00000008
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF begin ignored '#' on SIP/100-00000008
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF end '#' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:06] DTMF[13686] channel.c: DTMF end passthrough '#' on SIP/100-00000008
[Jun  2 17:18:06] DEBUG[13686] rtp.c: Difference is 16840, ms is 2125
[Jun  2 17:18:06] VERBOSE[13686] logger.c:     -- <SIP/100-00000008> Playing 'agent-pass' (language 'es')
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:06] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: Sending dtmf: 52 (4), at 192.168.222.45
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF begin '4' received on SIP/100-00000008
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF begin ignored '4' on SIP/100-00000008
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: Sending dtmf: 52 (4), at 192.168.222.45
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF end '4' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF end passthrough '4' on SIP/100-00000008
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000004 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: Sending dtmf: 51 (3), at 192.168.222.45
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF begin '3' received on SIP/100-00000008
[Jun  2 17:18:07] DTMF[13686] channel.c: DTMF begin ignored '3' on SIP/100-00000008
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:07] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: Sending dtmf: 51 (3), at 192.168.222.45
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end '3' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end passthrough '3' on SIP/100-00000008
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000003 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: Sending dtmf: 50 (2), at 192.168.222.45
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF begin '2' received on SIP/100-00000008
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF begin ignored '2' on SIP/100-00000008
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: Sending dtmf: 50 (2), at 192.168.222.45
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end '2' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end passthrough '2' on SIP/100-00000008
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000002 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF begin ignored '1' on SIP/100-00000008
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:08] DTMF[13686] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:08] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:18:09] DTMF[13686] channel.c: DTMF begin '#' received on SIP/100-00000008
[Jun  2 17:18:09] DTMF[13686] channel.c: DTMF begin ignored '#' on SIP/100-00000008
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:18:09] DTMF[13686] channel.c: DTMF end '#' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:09] DTMF[13686] channel.c: DTMF end passthrough '#' on SIP/100-00000008
[Jun  2 17:18:09] DEBUG[13686] rtp.c: Difference is 15360, ms is 1940
[Jun  2 17:18:09] VERBOSE[13686] logger.c:     -- <SIP/100-00000008> Playing 'agent-loginok' (language 'es')
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:09] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:18:11] DEBUG[13686] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:11] VERBOSE[13686] logger.c:     -- Started music on hold, class 'default', on SIP/100-00000008
[Jun  2 17:18:11] VERBOSE[13686] logger.c:   == Agent '1001' logged in (format gsm/gsm)
[Jun  2 17:18:11] DEBUG[13686] chan_agent.c: Checking availability of '1001'
[Jun  2 17:18:11] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:11] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:11] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:11] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:11] DEBUG[13686] chan_agent.c: Wrapup time for 1001 expired!
[Jun  2 17:18:11] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:11] DEBUG[13686] chan_agent.c: Checking availability of '1001'
[Jun  2 17:18:11] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:11] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:11] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:11] DEBUG[13686] res_musiconhold.c: SIP/100-00000008 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix'
[Jun  2 17:18:11] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:17] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: = No match Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for 6eea4ab6-80a9-498f-8137-1f682570c762 - INVITE (With RTP)
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: = Found Their Call ID: 6eea4ab6-80a9-498f-8137-1f682570c762 Their Tag f3cc71ab-a492-4cde-916d-0418048184fc Our tag: as00038a98
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Stopping retransmission on '6eea4ab6-80a9-498f-8137-1f682570c762' of Response 4727: Match Found
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: = Found Their Call ID: 6eea4ab6-80a9-498f-8137-1f682570c762 Their Tag f3cc71ab-a492-4cde-916d-0418048184fc Our tag: as00038a98
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing session-level SDP o=laptop-miguel 3484505897 0 IN IP4 192.168.222.45... UNSUPPORTED.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing session-level SDP s=sflphone... UNSUPPORTED.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.222.45... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 speex/16000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:112 speex/32000... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: T38 state changed to 0 on channel <none>
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: We're settling with these formats: 0x2 (gsm)
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Checking SIP call limits for device 101
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Updating call counter for incoming call
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: *** Our native formats are 0x2 (gsm) 
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: *** Joint capabilities are 0x2 (gsm) 
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: *** Our capabilities are 0x2 (gsm) 
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) 
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: This channel will not be able to handle video.
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: build_route: Contact hop: "miguel" <sip:101@192.168.222.45:47545>
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: SIP/101-00000009: New call is still down.... Trying... 
[Jun  2 17:18:17] DEBUG[13528] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:17] DEBUG[13687] pbx.c: Launching 'Answer'
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Executing [1100@default:1] Answer("SIP/101-00000009", "") in new stack
[Jun  2 17:18:17] DEBUG[13687] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: SIP answering channel: SIP/101-00000009
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: Setting framing from config on incoming call
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: True
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: -- Done with adding codecs to SDP
[Jun  2 17:18:17] DEBUG[13687] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm)
[Jun  2 17:18:17] DEBUG[13687] pbx.c: Launching 'Queue'
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Executing [1100@default:2] Queue("SIP/101-00000009", "test|ht") in new stack
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: queue: test, options: ht, url: (null), announce: (null), expires: 0, priority: 0
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: Queue test has no realtime members defined. No need for update
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: Queue 'test' Join, Channel 'SIP/101-00000009', Position '1'
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Started music on hold, class 'default', on SIP/101-00000009
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: There is 1 available member.
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: It's our turn (SIP/101-00000009).
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: = Found Their Call ID: 6eea4ab6-80a9-498f-8137-1f682570c762 Their Tag f3cc71ab-a492-4cde-916d-0418048184fc Our tag: as5db9202e
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:17] DEBUG[13528] chan_sip.c: Stopping retransmission on '6eea4ab6-80a9-498f-8137-1f682570c762' of Response 4728: Match Found
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: SIP/101-00000009 is trying to call a queue member.
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: Trying 'Agent/1001' with metric 999922
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Stopped music on hold on SIP/100-00000008
[Jun  2 17:18:17] DEBUG[13687] channel.c: Not copying variable SIPCALLID.
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:17] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:17] DEBUG[13687] channel.c: Not copying variable SIPDOMAIN.
[Jun  2 17:18:17] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:17] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:17] DEBUG[13687] channel.c: Not copying variable SIPURI.
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- agent_call, call to agent '1001' call on 'SIP/100-00000008'
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Playing beep, lang 'es'
[Jun  2 17:18:17] DEBUG[13687] channel.c: Thread -1216615536 Blocking 'SIP/100-00000008', already blocked by thread -1216369776 in procedure ast_waitfor_nandfds
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- <SIP/100-00000008> Playing 'beep' (language 'es')
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Played beep, result '0'
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Waited for stream, result '0'
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Set read format, result '0'
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Set write format, result '0'
[Jun  2 17:18:17] DEBUG[13687] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:17] DEBUG[13687] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:17] DEBUG[13686] chan_agent.c: agent_cont_sleep() returning 0
[Jun  2 17:18:17] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:17] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 3 (Busy)
[Jun  2 17:18:17] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '3' (Busy)
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Agent/1001 answered SIP/101-00000009
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Got RTCP report of 40 bytes
[Jun  2 17:18:17] VERBOSE[13687] logger.c:     -- Stopped music on hold on SIP/101-00000009
[Jun  2 17:18:17] DEBUG[13687] app_queue.c: Queue 'test' Leave, Channel 'SIP/101-00000009'
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:17] DEBUG[13687] chan_agent.c: Bridge on 'SIP/100-00000008' being set to 'Agent/1001' (3)
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Ooh, format changed from unknown to gsm
[Jun  2 17:18:17] DEBUG[13687] rtp.c: Created smoother: format: 2 ms: 20 len: 33
[Jun  2 17:18:21] DEBUG[13687] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:24] DEBUG[13687] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:27] DEBUG[13687] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:30] DEBUG[13687] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:32] DEBUG[13687] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: Sending dtmf: 42 (*), at 192.168.222.45
[Jun  2 17:18:34] DTMF[13687] channel.c: DTMF begin '*' received on SIP/100-00000008
[Jun  2 17:18:34] DTMF[13687] channel.c: DTMF begin passthrough '*' on SIP/100-00000008
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] rtp.c: Sending dtmf: 42 (*), at 192.168.222.45
[Jun  2 17:18:34] DTMF[13687] channel.c: DTMF end '*' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:18:34] DTMF[13687] channel.c: DTMF end accepted with begin '*' on SIP/100-00000008
[Jun  2 17:18:34] DTMF[13687] channel.c: DTMF end passthrough '*' on SIP/100-00000008
[Jun  2 17:18:34] DEBUG[13687] channel.c: Didn't get a frame from channel: Agent/1001
[Jun  2 17:18:34] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:34] DEBUG[13687] channel.c: Bridge stops bridging channels SIP/101-00000009 and Agent/1001
[Jun  2 17:18:34] DEBUG[13687] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Jun  2 17:18:34] DEBUG[13687] cdr_pgsql.c: cdr_pgsql: SQL command executed:  INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-06-02 17:18:17','101','101','1100','default', 'SIP/101-00000009','Agent/1001','Queue','test|ht',17,17,'ANSWERED',3,'','1275517097.11','agent-1001-1275517097-12.gsm')
[Jun  2 17:18:34] DEBUG[13687] channel.c: Hanging up channel 'Agent/1001'
[Jun  2 17:18:34] DEBUG[13687] chan_agent.c: Hangup called for state Up
[Jun  2 17:18:34] DEBUG[13687] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:34] VERBOSE[13687] logger.c:     -- Started music on hold, class 'default', on SIP/100-00000008
[Jun  2 17:18:34] DEBUG[13687] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:34] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:34] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13686] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun  2 17:18:34] DEBUG[13687] res_monitor.c: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/agent-1001-1275517097-12-in.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517097-12-out.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517097-12.gsm"  && rm -f "/var/spool/asterisk/monitor/agent-1001-1275517097-12-"* ) &
[Jun  2 17:18:34] DEBUG[13686] res_musiconhold.c: SIP/100-00000008 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix'
[Jun  2 17:18:34] DEBUG[13687] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:34] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:34] DEBUG[13687] pbx.c: Spawn extension (default,1100,2) exited non-zero on 'SIP/101-00000009'
[Jun  2 17:18:34] VERBOSE[13687] logger.c:   == Spawn extension (default, 1100, 2) exited non-zero on 'SIP/101-00000009'
[Jun  2 17:18:34] DEBUG[13687] channel.c: Soft-Hanging up channel 'SIP/101-00000009'
[Jun  2 17:18:34] DEBUG[13687] channel.c: Hanging up channel 'SIP/101-00000009'
[Jun  2 17:18:34] DEBUG[13687] chan_sip.c: Hangup call SIP/101-00000009, SIP callid 6eea4ab6-80a9-498f-8137-1f682570c762)
[Jun  2 17:18:34] DEBUG[13687] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:34] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:34] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:34] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:34] DEBUG[13528] chan_sip.c: = Found Their Call ID: 6eea4ab6-80a9-498f-8137-1f682570c762 Their Tag f3cc71ab-a492-4cde-916d-0418048184fc Our tag: as5db9202e
[Jun  2 17:18:34] DEBUG[13528] chan_sip.c: Stopping retransmission on '6eea4ab6-80a9-498f-8137-1f682570c762' of Request 102: Match Found
[Jun  2 17:18:34] VERBOSE[13528] logger.c: Really destroying SIP dialog '6eea4ab6-80a9-498f-8137-1f682570c762' Method: ACK
[Jun  2 17:18:35] DEBUG[13686] chan_agent.c: Wrapup time for 1001 expired!
[Jun  2 17:18:35] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:35] DEBUG[13686] chan_agent.c: Checking availability of '1001'
[Jun  2 17:18:35] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:35] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:35] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:37] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: = No match Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2 - INVITE (With RTP)
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: = Found Their Call ID: 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2 Their Tag 962c03f9-2b82-4a54-b897-3991f7ea326c Our tag: as7afb1492
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Stopping retransmission on '726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2' of Response 22645: Match Found
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: = Found Their Call ID: 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2 Their Tag 962c03f9-2b82-4a54-b897-3991f7ea326c Our tag: as7afb1492
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing session-level SDP o=laptop-miguel 3484505919 0 IN IP4 192.168.222.45... UNSUPPORTED.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing session-level SDP s=sflphone... UNSUPPORTED.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.222.45... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 speex/16000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:112 speex/32000... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: T38 state changed to 0 on channel <none>
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: We're settling with these formats: 0x2 (gsm)
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Checking SIP call limits for device 101
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Updating call counter for incoming call
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: *** Our native formats are 0x2 (gsm) 
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: *** Joint capabilities are 0x2 (gsm) 
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: *** Our capabilities are 0x2 (gsm) 
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) 
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: This channel will not be able to handle video.
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: build_route: Contact hop: "miguel" <sip:101@192.168.222.45:47545>
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: SIP/101-0000000a: New call is still down.... Trying... 
[Jun  2 17:18:39] DEBUG[13528] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:39] DEBUG[13693] pbx.c: Launching 'Answer'
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Executing [1100@default:1] Answer("SIP/101-0000000a", "") in new stack
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:39] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:39] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:39] DEBUG[13693] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: SIP answering channel: SIP/101-0000000a
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:39] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:39] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: Setting framing from config on incoming call
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: True
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: -- Done with adding codecs to SDP
[Jun  2 17:18:39] DEBUG[13693] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm)
[Jun  2 17:18:39] DEBUG[13693] pbx.c: Launching 'Queue'
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Executing [1100@default:2] Queue("SIP/101-0000000a", "test|ht") in new stack
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: queue: test, options: ht, url: (null), announce: (null), expires: 0, priority: 0
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: = Found Their Call ID: 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2 Their Tag 962c03f9-2b82-4a54-b897-3991f7ea326c Our tag: as12d1c094
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: Queue test has no realtime members defined. No need for update
[Jun  2 17:18:39] DEBUG[13528] chan_sip.c: Stopping retransmission on '726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2' of Response 22646: Match Found
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: Queue 'test' Join, Channel 'SIP/101-0000000a', Position '1'
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Started music on hold, class 'default', on SIP/101-0000000a
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: There is 1 available member.
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: It's our turn (SIP/101-0000000a).
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: SIP/101-0000000a is trying to call a queue member.
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: Trying 'Agent/1001' with metric 999995
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Stopped music on hold on SIP/100-00000008
[Jun  2 17:18:39] DEBUG[13693] channel.c: Not copying variable SIPCALLID.
[Jun  2 17:18:39] DEBUG[13693] channel.c: Not copying variable SIPDOMAIN.
[Jun  2 17:18:39] DEBUG[13693] channel.c: Not copying variable SIPURI.
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- agent_call, call to agent '1001' call on 'SIP/100-00000008'
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Playing beep, lang 'es'
[Jun  2 17:18:39] DEBUG[13693] channel.c: Thread -1216615536 Blocking 'SIP/100-00000008', already blocked by thread -1216369776 in procedure ast_waitfor_nandfds
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- <SIP/100-00000008> Playing 'beep' (language 'es')
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Played beep, result '0'
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Waited for stream, result '0'
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Set read format, result '0'
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Set write format, result '0'
[Jun  2 17:18:39] DEBUG[13693] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:39] DEBUG[13686] chan_agent.c: agent_cont_sleep() returning 0
[Jun  2 17:18:39] DEBUG[13693] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:39] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 3 (Busy)
[Jun  2 17:18:39] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '3' (Busy)
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Agent/1001 answered SIP/101-0000000a
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Got RTCP report of 40 bytes
[Jun  2 17:18:39] VERBOSE[13693] logger.c:     -- Stopped music on hold on SIP/101-0000000a
[Jun  2 17:18:39] DEBUG[13693] app_queue.c: Queue 'test' Leave, Channel 'SIP/101-0000000a'
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:39] DEBUG[13693] chan_agent.c: Bridge on 'SIP/100-00000008' being set to 'Agent/1001' (3)
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Ooh, format changed from unknown to gsm
[Jun  2 17:18:39] DEBUG[13693] rtp.c: Created smoother: format: 2 ms: 20 len: 33
[Jun  2 17:18:42] DEBUG[13693] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:45] DEBUG[13693] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:47] DEBUG[13693] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:49] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:18:49] DEBUG[13528] chan_sip.c: = Found Their Call ID: 18a39e1b0a645de47ef841f71951b69c@192.168.222.35 Their Tag  Our tag: as1462edb0
[Jun  2 17:18:49] DEBUG[13528] chan_sip.c: Stopping retransmission on '18a39e1b0a645de47ef841f71951b69c@192.168.222.35' of Request 102: Match Found
[Jun  2 17:18:49] VERBOSE[13528] logger.c: Really destroying SIP dialog '18a39e1b0a645de47ef841f71951b69c@192.168.222.35' Method: OPTIONS
[Jun  2 17:18:51] DEBUG[13528] chan_sip.c: = Found Their Call ID: 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2 Their Tag 962c03f9-2b82-4a54-b897-3991f7ea326c Our tag: as12d1c094
[Jun  2 17:18:51] DEBUG[13528] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jun  2 17:18:51] DEBUG[13528] chan_sip.c: Setting SIP_ALREADYGONE on dialog 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2
[Jun  2 17:18:51] DEBUG[13528] chan_sip.c: Received bye, issuing owner hangup
[Jun  2 17:18:51] DEBUG[13693] channel.c: Didn't get a frame from channel: SIP/101-0000000a
[Jun  2 17:18:51] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:51] DEBUG[13693] channel.c: Bridge stops bridging channels SIP/101-0000000a and Agent/1001
[Jun  2 17:18:51] DEBUG[13693] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Jun  2 17:18:51] DEBUG[13693] cdr_pgsql.c: cdr_pgsql: SQL command executed:  INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-06-02 17:18:39','101','101','1100','default', 'SIP/101-0000000a','Agent/1001','Queue','test|ht',12,12,'ANSWERED',3,'','1275517119.13','agent-1001-1275517119-14.gsm')
[Jun  2 17:18:51] DEBUG[13693] channel.c: Hanging up channel 'Agent/1001'
[Jun  2 17:18:51] DEBUG[13693] chan_agent.c: Hangup called for state Up
[Jun  2 17:18:51] DEBUG[13693] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:18:51] VERBOSE[13693] logger.c:     -- Started music on hold, class 'default', on SIP/100-00000008
[Jun  2 17:18:51] DEBUG[13693] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:51] DEBUG[13693] res_monitor.c: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/agent-1001-1275517119-14-in.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517119-14-out.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517119-14.gsm"  && rm -f "/var/spool/asterisk/monitor/agent-1001-1275517119-14-"* ) &
[Jun  2 17:18:51] DEBUG[13686] res_musiconhold.c: SIP/100-00000008 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix'
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:51] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:51] DEBUG[13693] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:51] DEBUG[13693] pbx.c: Spawn extension (default,1100,2) exited non-zero on 'SIP/101-0000000a'
[Jun  2 17:18:51] VERBOSE[13693] logger.c:   == Spawn extension (default, 1100, 2) exited non-zero on 'SIP/101-0000000a'
[Jun  2 17:18:51] DEBUG[13693] channel.c: Soft-Hanging up channel 'SIP/101-0000000a'
[Jun  2 17:18:51] DEBUG[13693] channel.c: Hanging up channel 'SIP/101-0000000a'
[Jun  2 17:18:51] DEBUG[13693] chan_sip.c: Hangup call SIP/101-0000000a, SIP callid 726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2)
[Jun  2 17:18:51] DEBUG[13693] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:18:51] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:18:51] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:18:51] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:51] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:18:52] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:52] VERBOSE[13528] logger.c: Really destroying SIP dialog '726b9a32-d681-4cf8-bf4d-fe0e8a67ecc2' Method: BYE
[Jun  2 17:18:52] DEBUG[13686] chan_agent.c: Wrapup time for 1001 expired!
[Jun  2 17:18:52] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:18:52] DEBUG[13686] chan_agent.c: Checking availability of '1001'
[Jun  2 17:18:52] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:18:52] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:18:52] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:18:54] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:18:54] DEBUG[13528] chan_sip.c: = Found Their Call ID: 2f1866107ea5703b6fefd0ef5a652064@192.168.222.35 Their Tag  Our tag: as00fba9fb
[Jun  2 17:18:54] DEBUG[13528] chan_sip.c: Stopping retransmission on '2f1866107ea5703b6fefd0ef5a652064@192.168.222.35' of Request 102: Match Found
[Jun  2 17:18:54] VERBOSE[13528] logger.c: Really destroying SIP dialog '2f1866107ea5703b6fefd0ef5a652064@192.168.222.35' Method: OPTIONS
[Jun  2 17:18:57] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:18:57] DEBUG[13539] chan_iax2.c: ip callno count decremented to 0 for 192.168.222.3
[Jun  2 17:18:57] DEBUG[13538] chan_iax2.c: ip callno count incremented to 1 for 192.168.222.3
[Jun  2 17:18:57] DEBUG[13529] chan_iax2.c: schedule decrement of callno used for 192.168.222.3 in 60 seconds
[Jun  2 17:18:57] DEBUG[13529] chan_iax2.c: Peer TRUNK_TEST_VIRT: got pong, lastms 18, historicms 18, maxms 2000
[Jun  2 17:18:57] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:18:57] DEBUG[13528] chan_sip.c: = Found Their Call ID: 2b523864625b1fc85893af4b60958d47@192.168.222.35 Their Tag  Our tag: as45229515
[Jun  2 17:18:57] DEBUG[13528] chan_sip.c: Stopping retransmission on '2b523864625b1fc85893af4b60958d47@192.168.222.35' of Request 102: Match Found
[Jun  2 17:18:57] VERBOSE[13528] logger.c: Really destroying SIP dialog '2b523864625b1fc85893af4b60958d47@192.168.222.35' Method: OPTIONS
[Jun  2 17:19:01] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:03] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: = No match Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c - INVITE (With RTP)
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: = Found Their Call ID: 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c Their Tag d4d0f916-1f91-4a8e-8600-993428debc94 Our tag: as35db5fd6
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Stopping retransmission on '1cfb86b1-7b18-4613-a11c-4fc4dba52c9c' of Response 10772: Match Found
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: = Found Their Call ID: 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c Their Tag d4d0f916-1f91-4a8e-8600-993428debc94 Our tag: as35db5fd6
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on RTP to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Setting NAT on UDPTL to Off
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing session-level SDP o=laptop-miguel 3484505948 0 IN IP4 192.168.222.45... UNSUPPORTED.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing session-level SDP s=sflphone... UNSUPPORTED.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.222.45... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 speex/16000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:112 speex/32000... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: T38 state changed to 0 on channel <none>
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: We're settling with these formats: 0x2 (gsm)
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Checking SIP call limits for device 101
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Updating call counter for incoming call
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: *** Our native formats are 0x2 (gsm) 
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: *** Joint capabilities are 0x2 (gsm) 
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: *** Our capabilities are 0x2 (gsm) 
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) 
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: This channel will not be able to handle video.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: build_route: Contact hop: "miguel" <sip:101@192.168.222.45:47545>
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: SIP/101-0000000b: New call is still down.... Trying... 
[Jun  2 17:19:08] DEBUG[13528] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:19:08] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:19:08] DEBUG[13701] pbx.c: Launching 'Answer'
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- Executing [1100@default:1] Answer("SIP/101-0000000b", "") in new stack
[Jun  2 17:19:08] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:19:08] DEBUG[13701] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: SIP answering channel: SIP/101-0000000b
[Jun  2 17:19:08] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: Setting framing from config on incoming call
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: True
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: -- Done with adding codecs to SDP
[Jun  2 17:19:08] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:19:08] DEBUG[13701] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm)
[Jun  2 17:19:08] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:19:08] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:19:08] DEBUG[13701] pbx.c: Launching 'Queue'
[Jun  2 17:19:08] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- Executing [1100@default:2] Queue("SIP/101-0000000b", "test|ht") in new stack
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: queue: test, options: ht, url: (null), announce: (null), expires: 0, priority: 0
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: Queue test has no realtime members defined. No need for update
[Jun  2 17:19:08] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: = Found Their Call ID: 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c Their Tag d4d0f916-1f91-4a8e-8600-993428debc94 Our tag: as7b49234c
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun  2 17:19:08] DEBUG[13528] chan_sip.c: Stopping retransmission on '1cfb86b1-7b18-4613-a11c-4fc4dba52c9c' of Response 10773: Match Found
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: Queue 'test' Join, Channel 'SIP/101-0000000b', Position '1'
[Jun  2 17:19:08] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- Started music on hold, class 'default', on SIP/101-0000000b
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: There is 1 available member.
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: It's our turn (SIP/101-0000000b).
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: SIP/101-0000000b is trying to call a queue member.
[Jun  2 17:19:08] DEBUG[13701] app_queue.c: Trying 'Agent/1001' with metric 999983
[Jun  2 17:19:08] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- Stopped music on hold on SIP/100-00000008
[Jun  2 17:19:08] DEBUG[13701] channel.c: Not copying variable SIPCALLID.
[Jun  2 17:19:08] DEBUG[13701] channel.c: Not copying variable SIPDOMAIN.
[Jun  2 17:19:08] DEBUG[13686] chan_agent.c: agent_cont_sleep() returning 0
[Jun  2 17:19:08] DEBUG[13701] channel.c: Not copying variable SIPURI.
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- agent_call, call to agent '1001' call on 'SIP/100-00000008'
[Jun  2 17:19:08] DEBUG[13701] chan_agent.c: Playing beep, lang 'es'
[Jun  2 17:19:08] VERBOSE[13701] logger.c:     -- <SIP/100-00000008> Playing 'beep' (language 'es')
[Jun  2 17:19:08] DEBUG[13701] chan_agent.c: Played beep, result '0'
[Jun  2 17:19:09] DEBUG[13701] chan_agent.c: Waited for stream, result '0'
[Jun  2 17:19:09] DEBUG[13701] chan_agent.c: Set read format, result '0'
[Jun  2 17:19:09] DEBUG[13701] chan_agent.c: Set write format, result '0'
[Jun  2 17:19:09] DEBUG[13701] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:19:09] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:09] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 3 (Busy)
[Jun  2 17:19:09] DEBUG[13701] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:09] VERBOSE[13701] logger.c:     -- Agent/1001 answered SIP/101-0000000b
[Jun  2 17:19:09] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '3' (Busy)
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Got RTCP report of 40 bytes
[Jun  2 17:19:09] VERBOSE[13701] logger.c:     -- Stopped music on hold on SIP/101-0000000b
[Jun  2 17:19:09] DEBUG[13701] app_queue.c: Queue 'test' Leave, Channel 'SIP/101-0000000b'
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:09] DEBUG[13701] chan_agent.c: Bridge on 'SIP/100-00000008' being set to 'Agent/1001' (3)
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Ooh, format changed from unknown to gsm
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Created smoother: format: 2 ms: 20 len: 33
[Jun  2 17:19:09] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:15] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:15] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF begin '#' received on SIP/100-00000008
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF begin passthrough '#' on SIP/100-00000008
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF begin '#' received on Agent/1001
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF begin passthrough '#' on Agent/1001
[Jun  2 17:19:17] DEBUG[13701] channel.c: Got DTMF begin on channel (Agent/1001)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] channel.c: Bridge stops bridging channels SIP/101-0000000b and Agent/1001
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Sending dtmf: 35 (#), at 192.168.222.45
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end '#' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end accepted with begin '#' on SIP/100-00000008
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end passthrough '#' on SIP/100-00000008
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end '#' received on Agent/1001, duration 120 ms
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end accepted with begin '#' on Agent/1001
[Jun  2 17:19:17] DTMF[13701] channel.c: DTMF end passthrough '#' on Agent/1001
[Jun  2 17:19:17] DEBUG[13701] channel.c: Got DTMF end on channel (Agent/1001)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] DEBUG[13701] channel.c: Bridge stops bridging channels SIP/101-0000000b and Agent/1001
[Jun  2 17:19:17] DEBUG[13701] res_features.c: Feature interpret: chan=SIP/101-0000000b, peer=Agent/1001, code=#, sense=2, features=6, dynamic=#
[Jun  2 17:19:17] DEBUG[13701] res_features.c: Feature detected: fname=Blind Transfer sname=blindxfer exten=#
[Jun  2 17:19:17] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:17] VERBOSE[13701] logger.c:     -- Started music on hold, class 'default', on SIP/101-0000000b
[Jun  2 17:19:17] VERBOSE[13701] logger.c:     -- <Agent/1001> Playing 'pbx-transfer' (language 'es')
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13701] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Jun  2 17:19:17] DEBUG[13670] res_musiconhold.c: SIP/101-0000000b Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix'
[Jun  2 17:19:17] DEBUG[13670] rtp.c: Difference is 1912, ms is 259
[Jun  2 17:19:17] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:17] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 648, ms is 101
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13701] channel.c: Set channel Agent/1001 to write format slin
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:18] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF begin passthrough '1' on SIP/100-00000008
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF begin '1' received on Agent/1001
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF begin ignored '1' on Agent/1001
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF end accepted with begin '1' on SIP/100-00000008
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF end '1' received on Agent/1001, duration 120 ms
[Jun  2 17:19:19] DTMF[13701] channel.c: DTMF end passthrough '1' on Agent/1001
[Jun  2 17:19:19] DEBUG[13701] channel.c: Set channel Agent/1001 to write format gsm
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:19] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin passthrough '1' on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin '1' received on Agent/1001
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin ignored '1' on Agent/1001
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF end accepted with begin '1' on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF end '1' received on Agent/1001, duration 120 ms
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF end passthrough '1' on Agent/1001
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:20] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin '0' received on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin passthrough '0' on SIP/100-00000008
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin '0' received on Agent/1001
[Jun  2 17:19:20] DTMF[13701] channel.c: DTMF begin ignored '0' on Agent/1001
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:20] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:21] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: Sending dtmf: 48 (0), at 192.168.222.45
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end '0' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end accepted with begin '0' on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end passthrough '0' on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end '0' received on Agent/1001, duration 120 ms
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end passthrough '0' on Agent/1001
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000000 (len = 4)
[Jun  2 17:19:21] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:21] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:21] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF begin '1' received on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF begin passthrough '1' on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF begin '1' received on Agent/1001
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF begin ignored '1' on Agent/1001
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13670] rtp.c: Difference is 640, ms is 100
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13701] rtp.c: Sending dtmf: 49 (1), at 192.168.222.45
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end '1' received on SIP/100-00000008, duration 120 ms
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end accepted with begin '1' on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end passthrough '1' on SIP/100-00000008
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end '1' received on Agent/1001, duration 120 ms
[Jun  2 17:19:21] DTMF[13701] channel.c: DTMF end passthrough '1' on Agent/1001
[Jun  2 17:19:21] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:21] VERBOSE[13701] logger.c:     -- Stopped music on hold on SIP/101-0000000b
[Jun  2 17:19:21] DEBUG[13701] channel.c: Hanging up channel 'Agent/1001'
[Jun  2 17:19:21] DEBUG[13701] chan_agent.c: Hangup called for state Up
[Jun  2 17:19:21] DEBUG[13701] rtp.c: Setting the marker bit due to a source update
[Jun  2 17:19:21] VERBOSE[13701] logger.c:     -- Started music on hold, class 'default', on SIP/100-00000008
[Jun  2 17:19:21] DEBUG[13701] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:19:21] DEBUG[13701] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Jun  2 17:19:21] DEBUG[13701] cdr_pgsql.c: cdr_pgsql: SQL command executed:  INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-06-02 17:19:08','101','101','1100','default', 'SIP/101-0000000b','Agent/1001','Queue','test|ht',13,13,'ANSWERED',3,'','1275517148.15','')
[Jun  2 17:19:21] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:21] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:19:21] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13686] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun  2 17:19:21] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:19:21] DEBUG[13701] res_monitor.c: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/agent-1001-1275517148-16-in.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517148-16-out.gsm" "/var/spool/asterisk/monitor/agent-1001-1275517148-16.gsm"  && rm -f "/var/spool/asterisk/monitor/agent-1001-1275517148-16-"* ) &
[Jun  2 17:19:21] DEBUG[13686] res_musiconhold.c: SIP/100-00000008 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix'
[Jun  2 17:19:21] DEBUG[13686] rtp.c: Difference is 16488, ms is 2081
[Jun  2 17:19:21] DEBUG[13701] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:19:21] DEBUG[13701] pbx.c: Launching 'Answer'
[Jun  2 17:19:21] VERBOSE[13701] logger.c:     -- Executing [1101@default:1] Answer("SIP/101-0000000b", "") in new stack
[Jun  2 17:19:21] DEBUG[13701] pbx.c: Launching 'Playback'
[Jun  2 17:19:21] VERBOSE[13701] logger.c:     -- Executing [1101@default:2] Playback("SIP/101-0000000b", "tt-monkeys") in new stack
[Jun  2 17:19:21] VERBOSE[13701] logger.c:     -- <SIP/101-0000000b> Playing 'tt-monkeys' (language 'es')
[Jun  2 17:19:21] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:21] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:19:21] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:19:22] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:22] DEBUG[13686] chan_agent.c: Wrapup time for 1001 expired!
[Jun  2 17:19:22] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:19:22] DEBUG[13686] chan_agent.c: Checking availability of '1001'
[Jun  2 17:19:22] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:22] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 1 (Not in use)
[Jun  2 17:19:22] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '1' (Not in use)
[Jun  2 17:19:24] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:29] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:29] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:35] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:36] DEBUG[13701] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:37] DEBUG[13701] pbx.c: Launching 'Hangup'
[Jun  2 17:19:37] VERBOSE[13701] logger.c:     -- Executing [1101@default:3] Hangup("SIP/101-0000000b", "") in new stack
[Jun  2 17:19:37] DEBUG[13701] pbx.c: Spawn extension (default,1101,3) exited non-zero on 'SIP/101-0000000b'
[Jun  2 17:19:37] VERBOSE[13701] logger.c:   == Spawn extension (default, 1101, 3) exited non-zero on 'SIP/101-0000000b'
[Jun  2 17:19:37] DEBUG[13701] channel.c: Soft-Hanging up channel 'SIP/101-0000000b'
[Jun  2 17:19:37] DEBUG[13701] channel.c: Hanging up channel 'SIP/101-0000000b'
[Jun  2 17:19:37] DEBUG[13701] chan_sip.c: Hangup call SIP/101-0000000b, SIP callid 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c)
[Jun  2 17:19:37] DEBUG[13701] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:19:37] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:19:37] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:19:37] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:19:37] DEBUG[13528] chan_sip.c: = Found Their Call ID: 1cfb86b1-7b18-4613-a11c-4fc4dba52c9c Their Tag d4d0f916-1f91-4a8e-8600-993428debc94 Our tag: as7b49234c
[Jun  2 17:19:37] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:19:37] DEBUG[13528] chan_sip.c: Stopping retransmission on '1cfb86b1-7b18-4613-a11c-4fc4dba52c9c' of Request 102: Match Found
[Jun  2 17:19:37] VERBOSE[13528] logger.c: Really destroying SIP dialog '1cfb86b1-7b18-4613-a11c-4fc4dba52c9c' Method: ACK
[Jun  2 17:19:38] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:43] DEBUG[13686] rtp.c: Got RTCP report of 84 bytes
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: = No match Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for 869352f4-58a5-4f86-a371-86add9055e69 - REGISTER (No RTP)
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: = Found Their Call ID: 869352f4-58a5-4f86-a371-86add9055e69 Their Tag 292e4c47-b0fd-48f1-884b-3f36c377b244 Our tag: as671ffed0
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:19:44] DEBUG[13528] devicestate.c: Notification of state change to be queued on device/channel SIP/101
[Jun  2 17:19:44] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 101
[Jun  2 17:19:44] DEBUG[13521] chan_sip.c: Checking device state for peer 101
[Jun  2 17:19:44] DEBUG[13521] devicestate.c: Changing state for SIP/101 - state 1 (Not in use)
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: = Found Their Call ID: 62bb11632a84df1d7eaf79743b35f0e6@192.168.222.35 Their Tag  Our tag: as45611a30
[Jun  2 17:19:44] DEBUG[13528] chan_sip.c: Stopping retransmission on '62bb11632a84df1d7eaf79743b35f0e6@192.168.222.35' of Request 102: Match Found
[Jun  2 17:19:44] VERBOSE[13528] logger.c: Really destroying SIP dialog '62bb11632a84df1d7eaf79743b35f0e6@192.168.222.35' Method: OPTIONS
[Jun  2 17:19:44] DEBUG[13524] app_queue.c: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:19:45] DEBUG[13686] rtp.c: Got RTCP report of 68 bytes
[Jun  2 17:19:45] DEBUG[13528] chan_sip.c: = No match Their Call ID: 869352f4-58a5-4f86-a371-86add9055e69 Their Tag 292e4c47-b0fd-48f1-884b-3f36c377b244 Our tag: as671ffed0
[Jun  2 17:19:45] DEBUG[13528] chan_sip.c: = Found Their Call ID: MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE. Their Tag 308e4b0e Our tag: as576c9e48
[Jun  2 17:19:45] DEBUG[13528] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jun  2 17:19:45] DEBUG[13528] chan_sip.c: Setting SIP_ALREADYGONE on dialog MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE.
[Jun  2 17:19:45] DEBUG[13528] chan_sip.c: Received bye, issuing owner hangup
[Jun  2 17:19:45] VERBOSE[13686] logger.c:     -- Stopped music on hold on SIP/100-00000008
[Jun  2 17:19:45] VERBOSE[13686] logger.c:   == Agent '1001' logged out
[Jun  2 17:19:45] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel Agent/1001
[Jun  2 17:19:45] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for Agent - 1001
[Jun  2 17:19:45] DEBUG[13686] pbx.c: Spawn extension (default,7700,1) exited non-zero on 'SIP/100-00000008'
[Jun  2 17:19:45] DEBUG[13521] devicestate.c: Changing state for Agent/1001 - state 5 (Unavailable)
[Jun  2 17:19:45] VERBOSE[13686] logger.c:   == Spawn extension (default, 7700, 1) exited non-zero on 'SIP/100-00000008'
[Jun  2 17:19:45] DEBUG[13686] channel.c: Soft-Hanging up channel 'SIP/100-00000008'
[Jun  2 17:19:45] DEBUG[13524] app_queue.c: Device 'Agent/1001' changed to state '5' (Unavailable)
[Jun  2 17:19:45] DEBUG[13686] channel.c: Hanging up channel 'SIP/100-00000008'
[Jun  2 17:19:45] DEBUG[13686] chan_sip.c: Hangup call SIP/100-00000008, SIP callid MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE.)
[Jun  2 17:19:45] DEBUG[13686] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Jun  2 17:19:45] DEBUG[13686] cdr_pgsql.c: cdr_pgsql: SQL command executed:  INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2010-06-02 17:18:02','"100" <100>','100','7700','default', 'Agent/1001','','AgentLogin','',103,103,'ANSWERED',3,'','1275517082.10','')
[Jun  2 17:19:45] DEBUG[13686] devicestate.c: Notification of state change to be queued on device/channel SIP/100
[Jun  2 17:19:45] DEBUG[13521] devicestate.c: No provider found, checking channel drivers for SIP - 100
[Jun  2 17:19:45] DEBUG[13521] chan_sip.c: Checking device state for peer 100
[Jun  2 17:19:45] DEBUG[13521] devicestate.c: Changing state for SIP/100 - state 1 (Not in use)
[Jun  2 17:19:45] DEBUG[13524] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun  2 17:19:46] VERBOSE[13528] logger.c: Really destroying SIP dialog 'MGUyMGJkMTQ5MDk4OGMxMWIxNWUzOGU5NmJmYWNjODE.' Method: BYE
[Jun  2 17:19:50] VERBOSE[13684] logger.c:     -- Remote UNIX connection disconnected
[Jun  2 17:19:54] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:19:54] DEBUG[13528] chan_sip.c: = Found Their Call ID: 1126658329ca039f342e61833326a37a@192.168.222.35 Their Tag  Our tag: as3e2925cc
[Jun  2 17:19:54] DEBUG[13528] chan_sip.c: Stopping retransmission on '1126658329ca039f342e61833326a37a@192.168.222.35' of Request 102: Match Found
[Jun  2 17:19:54] VERBOSE[13528] logger.c: Really destroying SIP dialog '1126658329ca039f342e61833326a37a@192.168.222.35' Method: OPTIONS
[Jun  2 17:19:57] DEBUG[13539] chan_iax2.c: ip callno count decremented to 0 for 192.168.222.3
[Jun  2 17:19:57] DEBUG[13531] chan_iax2.c: ip callno count incremented to 1 for 192.168.222.3
[Jun  2 17:19:57] DEBUG[13532] chan_iax2.c: schedule decrement of callno used for 192.168.222.3 in 60 seconds
[Jun  2 17:19:57] DEBUG[13532] chan_iax2.c: Peer TRUNK_TEST_VIRT: got pong, lastms 17, historicms 17, maxms 2000
[Jun  2 17:19:57] DEBUG[13528] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun  2 17:19:57] DEBUG[13528] chan_sip.c: = Found Their Call ID: 796c9d33695c6e2243c18e8600c7264e@192.168.222.35 Their Tag  Our tag: as27259156
[Jun  2 17:19:57] DEBUG[13528] chan_sip.c: Stopping retransmission on '796c9d33695c6e2243c18e8600c7264e@192.168.222.35' of Request 102: Match Found
[Jun  2 17:19:57] VERBOSE[13528] logger.c: Really destroying SIP dialog '796c9d33695c6e2243c18e8600c7264e@192.168.222.35' Method: OPTIONS