Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Set("SIP/5895-45e1", "__SavedEXTEN=0412938232") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing NoOp("SIP/5895-45e1", "") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing NoOp("SIP/5895-45e1", "") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "OfficeServ500Ext|0412938232|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (OfficeServ500Ext,0412938232,1)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Sent into invalid extension '0412938232' in context 'OfficeServ500Ext' on SIP/5895-45e1
Feb 15 00:08:49 DEBUG[25235] pbx.c: Function result is '0380805895'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "SIP-to-OS500-PreDialout|0380805895|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (SIP-to-OS500-PreDialout,0380805895,1)
Feb 15 00:08:49 DEBUG[25235] pbx.c: Function result is '20060215-000849'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MixMonitor("SIP/5895-45e1", "BorisHome-20060215-000849-Out-0412938232.WAV|b|mv ^{MIXMONITOR_FILENAME} /var/spool/asterisk/monitor/Boris") in new stack
Feb 15 00:08:49 DEBUG[25236] channel.c: Spy MixMonitor added to channel SIP/5895-45e1
Feb 15 00:08:49 VERBOSE[25236] logger.c:   == Begin MixMonitor Recording SIP/5895-45e1
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "i|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (SIP-to-OS500-PreDialout,i,1)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "SIP-to-OS500-Dialout|0412938232|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (SIP-to-OS500-Dialout,0412938232,1)
Feb 15 00:08:49 DEBUG[25217] res_config_mysql.c: MySQL RealTime: Everything is fine.
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Sent into invalid extension '0412938232' in context 'SIP-to-OS500-Dialout' on SIP/5895-45e1
Feb 15 00:08:49 DEBUG[25235] pbx.c: Function result is '0380805895'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "Lookup-LCR-for-SIP-Clients|0380805895|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,1)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MYSQL("SIP/5895-45e1", "Connect connid 127.0.0.1 user pass asterisk") in new stack
Feb 15 00:08:49 DEBUG[25217] db.c: Unable to find key '5895' in family 'SIP/Registry'
Feb 15 00:08:49 DEBUG[25235] pbx.c: Function result is '0380805895'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MYSQL("SIP/5895-45e1", "Query resultid 1 SELECT lcr FROM sip_user_features WHERE user=0380805895") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MYSQL("SIP/5895-45e1", "Fetch fetchid 2 SUElcr") in new stack
Feb 15 00:08:49 DEBUG[25235] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=1
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing NoOp("SIP/5895-45e1", "10001") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MYSQL("SIP/5895-45e1", "Clear 2") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing MYSQL("SIP/5895-45e1", "Disconnect 1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing GotoIf("SIP/5895-45e1", "1?8:10") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,8)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Set("SIP/5895-45e1", "LCR=10001") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "i|2") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,i,2)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Goto("SIP/5895-45e1", "Out-SIP-Clients|0412938232|1") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (Out-SIP-Clients,0412938232,1)
Feb 15 00:08:49 DEBUG[25235] pbx.c: Expression result is '0'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing GotoIf("SIP/5895-45e1", "0?102") in new stack
Feb 15 00:08:49 DEBUG[25235] pbx.c: Not taking any branch
Feb 15 00:08:49 DEBUG[25235] pbx.c: Expression result is '1'
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing GotoIf("SIP/5895-45e1", "1?410") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Goto (Out-SIP-Clients,0412938232,410)
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing SetAMAFlags("SIP/5895-45e1", "billing") in new stack
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Executing Dial("SIP/5895-45e1", "SIP/18310412938232@vblue2s|120|r") in new stack
Feb 15 00:08:49 DEBUG[25235] chan_sip.c: Setting NAT on RTP to 0
Feb 15 00:08:49 DEBUG[25235] chan_sip.c: Outgoing Call for 18310412938232
Feb 15 00:08:49 VERBOSE[25235] logger.c:     -- Called 18310412938232@vblue2s
Feb 15 00:08:51 VERBOSE[25235] logger.c:     -- SIP/vblue2s-16db is ringing
Feb 15 00:08:51 DEBUG[25235] chan_sip.c: Acked pending invite 102
Feb 15 00:08:51 VERBOSE[25235] logger.c:   == Spawn extension (Out-SIP-Clients, 0412938232, 411) exited non-zero on 'SIP/5895-45e1'
Feb 15 00:08:51 DEBUG[25235] channel.c: Spy MixMonitor removed from channel SIP/5895-45e1
Feb 15 00:08:51 VERBOSE[25236] logger.c:   == End MixMonitor Recording SIP/5895-45e1
Feb 15 00:08:51 VERBOSE[25236] logger.c:   == Executing [mv  /var/spool/asterisk/monitor/Boris]
Feb 15 00:09:08 DEBUG[25222] chan_sip.c: build_route: Contact hop: <sip:5895@220.253.113.213:5060>
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Set("SIP/5895-496b", "__SavedEXTEN=0412938232") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing NoOp("SIP/5895-496b", "") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing NoOp("SIP/5895-496b", "") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "OfficeServ500Ext|0412938232|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (OfficeServ500Ext,0412938232,1)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Sent into invalid extension '0412938232' in context 'OfficeServ500Ext' on SIP/5895-496b
Feb 15 00:09:08 DEBUG[25243] pbx.c: Function result is '0380805895'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "SIP-to-OS500-PreDialout|0380805895|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (SIP-to-OS500-PreDialout,0380805895,1)
Feb 15 00:09:08 DEBUG[25243] pbx.c: Function result is '20060215-000908'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MixMonitor("SIP/5895-496b", "BorisHome-20060215-000908-Out-0412938232.WAV|b|mv ^{MIXMONITOR_FILENAME} /var/spool/asterisk/monitor/Boris") in new stack
Feb 15 00:09:08 DEBUG[25245] channel.c: Spy MixMonitor added to channel SIP/5895-496b
Feb 15 00:09:08 VERBOSE[25245] logger.c:   == Begin MixMonitor Recording SIP/5895-496b
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "i|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (SIP-to-OS500-PreDialout,i,1)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "SIP-to-OS500-Dialout|0412938232|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (SIP-to-OS500-Dialout,0412938232,1)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Sent into invalid extension '0412938232' in context 'SIP-to-OS500-Dialout' on SIP/5895-496b
Feb 15 00:09:08 DEBUG[25243] pbx.c: Function result is '0380805895'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "Lookup-LCR-for-SIP-Clients|0380805895|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,1)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MYSQL("SIP/5895-496b", "Connect connid 127.0.0.1 user pass asterisk") in new stack
Feb 15 00:09:08 DEBUG[25243] pbx.c: Function result is '0380805895'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MYSQL("SIP/5895-496b", "Query resultid 1 SELECT lcr FROM sip_user_features WHERE user=0380805895") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MYSQL("SIP/5895-496b", "Fetch fetchid 2 SUElcr") in new stack
Feb 15 00:09:08 DEBUG[25243] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=1
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing NoOp("SIP/5895-496b", "10001") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MYSQL("SIP/5895-496b", "Clear 2") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing MYSQL("SIP/5895-496b", "Disconnect 1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing GotoIf("SIP/5895-496b", "1?8:10") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,8)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Set("SIP/5895-496b", "LCR=10001") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "i|2") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,i,2)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Goto("SIP/5895-496b", "Out-SIP-Clients|0412938232|1") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (Out-SIP-Clients,0412938232,1)
Feb 15 00:09:08 DEBUG[25243] pbx.c: Expression result is '0'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing GotoIf("SIP/5895-496b", "0?102") in new stack
Feb 15 00:09:08 DEBUG[25243] pbx.c: Not taking any branch
Feb 15 00:09:08 DEBUG[25243] pbx.c: Expression result is '1'
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing GotoIf("SIP/5895-496b", "1?410") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Goto (Out-SIP-Clients,0412938232,410)
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing SetAMAFlags("SIP/5895-496b", "billing") in new stack
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Executing Dial("SIP/5895-496b", "SIP/18310412938232@vblue2s|120|r") in new stack
Feb 15 00:09:08 DEBUG[25243] chan_sip.c: Setting NAT on RTP to 0
Feb 15 00:09:08 DEBUG[25243] chan_sip.c: Outgoing Call for 18310412938232
Feb 15 00:09:08 VERBOSE[25243] logger.c:     -- Called 18310412938232@vblue2s
Feb 15 00:09:09 DEBUG[25243] chan_sip.c: Acked pending invite 102
Feb 15 00:09:09 VERBOSE[25243] logger.c:   == Spawn extension (Out-SIP-Clients, 0412938232, 411) exited non-zero on 'SIP/5895-496b'
Feb 15 00:09:09 DEBUG[25243] channel.c: Spy MixMonitor removed from channel SIP/5895-496b
Feb 15 00:09:09 VERBOSE[25245] logger.c:   == End MixMonitor Recording SIP/5895-496b
Feb 15 00:09:09 VERBOSE[25245] logger.c:   == Executing [mv  /var/spool/asterisk/monitor/Boris]
Feb 15 00:09:20 DEBUG[25222] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 3422, ours 3422)
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: * SIP extension value: 0 for call a3d50a6d-37fce1e@192.168.1.51
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: Setting NAT on RTP to 524288
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: Checking SIP call limits for device 5895
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: Updating call counter for incoming call
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: build_route: Contact hop: <sip:5895@220.253.113.213:5060>
Feb 15 00:09:23 DEBUG[25217] chan_sip.c: Checking device state for peer 5895
Feb 15 00:09:23 DEBUG[25217] devicestate.c: Changing state for SIP/5895 - state 5 (Unavailable)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Set'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Set("SIP/5895-9950", "__SavedEXTEN=0412938232") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'NoOp'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing NoOp("SIP/5895-9950", "") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'NoOp'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing NoOp("SIP/5895-9950", "") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "OfficeServ500Ext|0412938232|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (OfficeServ500Ext,0412938232,1)
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Sent into invalid extension '0412938232' in context 'OfficeServ500Ext' on SIP/5895-9950
Feb 15 00:09:23 DEBUG[25250] pbx.c: Function result is '0380805895'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "SIP-to-OS500-PreDialout|0380805895|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (SIP-to-OS500-PreDialout,0380805895,1)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Function result is '20060215-000923'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MixMonitor'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MixMonitor("SIP/5895-9950", "BorisHome-20060215-000923-Out-0412938232.WAV|b|mv ^{MIXMONITOR_FILENAME} /var/spool/asterisk/monitor/Boris") in new stack
Feb 15 00:09:23 DEBUG[25217] chan_sip.c: Checking device state for peer 5895
Feb 15 00:09:23 DEBUG[25252] channel.c: Spy MixMonitor added to channel SIP/5895-9950
Feb 15 00:09:23 VERBOSE[25252] logger.c:   == Begin MixMonitor Recording SIP/5895-9950
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "i|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (SIP-to-OS500-PreDialout,i,1)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "SIP-to-OS500-Dialout|0412938232|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (SIP-to-OS500-Dialout,0412938232,1)
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Sent into invalid extension '0412938232' in context 'SIP-to-OS500-Dialout' on SIP/5895-9950
Feb 15 00:09:23 DEBUG[25250] pbx.c: Function result is '0380805895'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "Lookup-LCR-for-SIP-Clients|0380805895|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,1)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MYSQL'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MYSQL("SIP/5895-9950", "Connect connid 127.0.0.1 user pass asterisk") in new stack
Feb 15 00:09:23 DEBUG[25251] app_queue.c: Device 'SIP/5895' changed to state '5' (Unavailable)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Function result is '0380805895'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MYSQL'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MYSQL("SIP/5895-9950", "Query resultid 1 SELECT lcr FROM sip_user_features WHERE user=0380805895") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MYSQL'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MYSQL("SIP/5895-9950", "Fetch fetchid 2 SUElcr") in new stack
Feb 15 00:09:23 DEBUG[25250] app_addon_sql_mysql.c: ast_MYSQL_fetch: numFields=1
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'NoOp'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing NoOp("SIP/5895-9950", "10001") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MYSQL'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MYSQL("SIP/5895-9950", "Clear 2") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'MYSQL'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing MYSQL("SIP/5895-9950", "Disconnect 1") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'GotoIf'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing GotoIf("SIP/5895-9950", "1?8:10") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,0380805895,8)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Set'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Set("SIP/5895-9950", "LCR=10001") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "i|2") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (Lookup-LCR-for-SIP-Clients,i,2)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Goto'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Goto("SIP/5895-9950", "Out-SIP-Clients|0412938232|1") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (Out-SIP-Clients,0412938232,1)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Expression result is '0'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'GotoIf'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing GotoIf("SIP/5895-9950", "0?102") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Not taking any branch
Feb 15 00:09:23 DEBUG[25250] pbx.c: Expression result is '1'
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'GotoIf'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing GotoIf("SIP/5895-9950", "1?410") in new stack
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Goto (Out-SIP-Clients,0412938232,410)
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'SetAMAFlags'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing SetAMAFlags("SIP/5895-9950", "billing") in new stack
Feb 15 00:09:23 DEBUG[25250] pbx.c: Launching 'Dial'
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Executing Dial("SIP/5895-9950", "SIP/18310412938232@vblue2s|120|r") in new stack
Feb 15 00:09:23 DEBUG[25250] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Feb 15 00:09:23 DEBUG[25250] chan_sip.c: Setting NAT on RTP to 0
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Out-SIP-Clients-0412938232-411.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Out-SIP-Clients-0412938232-410.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Out-SIP-Clients-0412938232-2.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Out-SIP-Clients-0412938232-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-i-2.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-9.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable LCR.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-8.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-7.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable MYSQL_STATUS.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-6.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-5.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-4.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable fetchid.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable SUElcr.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-3.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable resultid.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-2.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable connid.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-Lookup-LCR-for-SIP-Clients-0380805895-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-SIP-to-OS500-Dialout-i-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable INVALID_EXTEN.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-SIP-to-OS500-PreDialout-i-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-SIP-to-OS500-PreDialout-0380805895-2.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable MIXMONITOR_FILENAME.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-SIP-to-OS500-PreDialout-0380805895-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-OfficeServ500Ext-i-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-From-SIP-Client-0412938232-4.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-From-SIP-Client-0412938232-3.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-From-SIP-Client-0412938232-2.
Feb 15 00:09:23 DEBUG[25250] channel.c: Copying hard-transferable variable SavedEXTEN.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable STACK-From-SIP-Client-0412938232-1.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable SIPCALLID.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable SIPUSERAGENT.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable SIPDOMAIN.
Feb 15 00:09:23 DEBUG[25250] channel.c: Not copying variable SIPURI.
Feb 15 00:09:23 DEBUG[25250] chan_sip.c: Outgoing Call for 18310412938232
Feb 15 00:09:23 DEBUG[25250] chan_sip.c: Updating call counter for outgoing call
Feb 15 00:09:23 VERBOSE[25250] logger.c:     -- Called 18310412938232@vblue2s
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: = Found Their Call ID: 686c7aa81fcf29ed2f100df14bc4e092@192.168.100.202 Their Tag  Our tag: as67b8de1b
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '686c7aa81fcf29ed2f100df14bc4e092@192.168.100.202' Request 102: Found
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: SIP response 100 to standard invite
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: = Found Their Call ID: 876b9233-d2ee1441@192.168.3.11 Their Tag ec87eaab52cd629o0 Our tag: as36a7aa57
Feb 15 00:09:23 DEBUG[25222] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 3422, ours 3422)
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: = Found Their Call ID: 61e9d2a3-b974e91@192.168.3.11 Their Tag d552f69b8b43baf9o1 Our tag: as4a768c1a
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: Ignoring SIP message because of retransmit (REGISTER Seqno 15793, ours 15793)
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: = Found Their Call ID: a3d50a6d-37fce1e@192.168.1.51 Their Tag d63ff6217d40b5fao0 Our tag: as26994fcf
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL
Feb 15 00:09:24 DEBUG[25250] channel.c: Hanging up channel 'SIP/vblue2s-b9e3'
Feb 15 00:09:24 DEBUG[25250] chan_sip.c: Updating call counter for outgoing call
Feb 15 00:09:24 DEBUG[25250] chan_sip.c: Acked pending invite 102
Feb 15 00:09:24 DEBUG[25250] chan_sip.c: Stopping retransmission on '686c7aa81fcf29ed2f100df14bc4e092@192.168.100.202' of Request 102: Match Found
Feb 15 00:09:24 DEBUG[25250] chan_sip.c: Stopping retransmission on '686c7aa81fcf29ed2f100df14bc4e092@192.168.100.202' of Request 102: Match Found
Feb 15 00:09:24 DEBUG[25250] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Feb 15 00:09:24 DEBUG[25250] pbx.c: Spawn extension (Out-SIP-Clients,0412938232,411) exited non-zero on 'SIP/5895-9950'
Feb 15 00:09:24 DEBUG[25217] chan_sip.c: Checking device state for peer vblue2s
Feb 15 00:09:24 DEBUG[25217] devicestate.c: Changing state for SIP/vblue2s - state 1 (Not in use)
Feb 15 00:09:24 VERBOSE[25252] logger.c:   == End MixMonitor Recording SIP/5895-9950
Feb 15 00:09:24 VERBOSE[25252] logger.c:   == Executing [mv /var/spool/asterisk/monitor/BorisHome-20060215-000923-Out-0412938232.WAV /var/spool/asterisk/monitor/Boris]
Feb 15 00:09:24 DEBUG[25255] app_queue.c: Device 'SIP/vblue2s' changed to state '1' (Not in use)
Feb 15 00:09:24 DEBUG[25250] channel.c: Spy MixMonitor removed from channel SIP/5895-9950
Feb 15 00:09:24 DEBUG[25250] cdr.c: CDR detaching from this thread
Feb 15 00:09:24 DEBUG[25250] channel.c: Hanging up channel 'SIP/5895-9950'
Feb 15 00:09:24 DEBUG[25250] chan_sip.c: Updating call counter for incoming call
Feb 15 00:09:24 DEBUG[25217] chan_sip.c: Checking device state for peer 5895
Feb 15 00:09:24 DEBUG[25217] devicestate.c: Changing state for SIP/5895 - state 5 (Unavailable)
Feb 15 00:09:24 DEBUG[25256] app_queue.c: Device 'SIP/5895' changed to state '5' (Unavailable)
Feb 15 00:09:24 DEBUG[25217] chan_sip.c: Checking device state for peer 5895
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: Updating call counter for outgoing call
Feb 15 00:09:24 VERBOSE[25222] logger.c: Really destroying SIP dialog '686c7aa81fcf29ed2f100df14bc4e092@192.168.100.202' Method: INVITE
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: = Found Their Call ID: a3d50a6d-37fce1e@192.168.1.51 Their Tag d63ff6217d40b5fao0 Our tag: as26994fcf
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
Feb 15 00:09:24 DEBUG[25222] chan_sip.c: Stopping retransmission on 'a3d50a6d-37fce1e@192.168.1.51' of Response 102: Match Found
Feb 15 00:09:24 VERBOSE[25222] logger.c: Really destroying SIP dialog 'a3d50a6d-37fce1e@192.168.1.51' Method: ACK