[Oct 8 10:14:28] Asterisk SVN-branch-12-r400661 built by root @ on a i686 running Linux on 2013-10-01 16:12:22 UTC [Oct 8 10:14:28] VERBOSE[9658] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Oct 8 10:14:28] VERBOSE[9658] logger.c: Asterisk Queue Logger restarted [Oct 8 10:14:30] WARNING[9540] res_pjsip_pubsub.c: Subscriptions not permitted for endpoint phone_A. [Oct 8 10:14:30] WARNING[9540] res_pjsip_pubsub.c: Subscriptions not permitted for endpoint phone_A. [Oct 8 10:14:42] Asterisk SVN-branch-12-r400661 built by root @ putang2 on a i686 running Linux on 2013-10-01 16:12:22 UTC [Oct 8 10:14:42] DEBUG[9658] config.c: Parsing /etc/asterisk/logger.conf [Oct 8 10:14:42] VERBOSE[9658] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Oct 8 10:14:42] VERBOSE[9658] logger.c: Asterisk Queue Logger restarted [Oct 8 10:14:43] VERBOSE[9540] res_pjsip_registrar.c: -- Added contact 'sip:phone_B@10.24.18.165:5060;ob' to AOR 'phone_B' with expiration of 300 seconds [Oct 8 10:14:43] DEBUG[9526] devicestate.c: Processing device state change for 'PJSIP/phone_B' [Oct 8 10:14:43] DEBUG[9526] devicestate.c: Adding per-server state of 'Not in use' for 'PJSIP/phone_B' [Oct 8 10:14:43] DEBUG[9526] devicestate.c: Aggregate devstate result is 'Not in use' for 'PJSIP/phone_B' [Oct 8 10:14:43] DEBUG[9526] devicestate.c: Aggregate state for device 'PJSIP/phone_B' has changed to 'Not in use' [Oct 8 10:14:43] WARNING[9540] res_pjsip_pubsub.c: Subscriptions not permitted for endpoint phone_B. [Oct 8 10:14:43] WARNING[9540] res_pjsip_pubsub.c: Subscriptions not permitted for endpoint phone_B. [Oct 8 10:14:43] WARNING[9540] res_pjsip_pubsub.c: Subscriptions not permitted for endpoint phone_A. [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8dbb4c4' [Oct 8 10:14:45] DEBUG[9540] res_rtp_asterisk.c: Allocated port 19120 for RTP instance '0x8dbb4c4' [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: RTP instance '0x8dbb4c4' is setup and ready to go [Oct 8 10:14:45] DEBUG[9540] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8dbb4c4' [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 0 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 8 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 9 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 111 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 18 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 58 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 118 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 58 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 96 based on m type on 0xb5d61548 [Oct 8 10:14:45] DEBUG[9668][C-00000000] pbx.c: Launching 'AgentLogin' [Oct 8 10:14:45] VERBOSE[9668][C-00000000] pbx.c: -- Executing [551@internal:1] AgentLogin("PJSIP/phone_A-00000000", "1001") in new stack [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Chose bridge technology holding_bridge [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c: calling holding_bridge technology constructor [Oct 8 10:14:45] DEBUG[9668][C-00000000] bridge.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c: calling holding_bridge technology start [Oct 8 10:14:45] DEBUG[9526] devicestate.c: Processing device state change for 'PJSIP/phone_A' [Oct 8 10:14:45] DEBUG[9526] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/phone_A' [Oct 8 10:14:45] DEBUG[9526] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/phone_A' [Oct 8 10:14:45] DEBUG[9526] devicestate.c: Aggregate state for device 'PJSIP/phone_A' has changed to 'In use' [Oct 8 10:14:45] DEBUG[9540] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8dbb4c4' [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 0 based on m type on 0xb5d60fd8 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 8 based on m type on 0xb5d60fd8 [Oct 8 10:14:45] DEBUG[9540] rtp_engine.c: Setting payload 96 based on m type on 0xb5d60fd8 [Oct 8 10:14:46] DEBUG[9668][C-00000000] res_rtp_asterisk.c: 0x8c8a660 -- Probation learning mode pass with source address 10.24.19.97:4054 [Oct 8 10:14:46] DEBUG[9668][C-00000000] channel.c: Set channel PJSIP/phone_A-00000000 to write format gsm [Oct 8 10:14:46] DEBUG[9668][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Oct 8 10:14:46] DEBUG[9668][C-00000000] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Oct 8 10:14:46] DEBUG[9668][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 8 10:14:46] VERBOSE[9668][C-00000000] file.c: -- Playing 'agent-loginok.gsm' (language 'en') [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Set channel PJSIP/phone_A-00000000 to write format ulaw [Oct 8 10:14:47] VERBOSE[9668][C-00000000] app_agent_pool.c: == Agent '1001' logged in (format ulaw/ulaw) [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge_channel.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c: 0xb37e819c(PJSIP/phone_A-00000000) is joining [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge_channel.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c: pushing 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge.c: Putting interval hook 0xb6f0394c with interval 1000 in the heap on features 0xb2aa4ae4 [Oct 8 10:14:47] VERBOSE[9668][C-00000000] bridge_channel.c: -- Channel PJSIP/phone_A-00000000 joined 'holding_bridge' agent_hold-bridge <637a4c3b-3bef-447e-9b04-edb4183d990c> [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c is happy that channel PJSIP/phone_A-00000000 already has read format ulaw [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c is happy that channel PJSIP/phone_A-00000000 already has write format ulaw [Oct 8 10:14:47] DEBUG[9668][C-00000000] bridge.c: Bridge 637a4c3b-3bef-447e-9b04-edb4183d990c: 0xb37e819c(PJSIP/phone_A-00000000) is joining holding_bridge technology [Oct 8 10:14:47] VERBOSE[9668][C-00000000] res_musiconhold.c: -- Started music on hold, class 'default', on PJSIP/phone_A-00000000 [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Oct 8 10:14:47] DEBUG[9668][C-00000000] channel.c: Set channel PJSIP/phone_A-00000000 to write format slin [Oct 8 10:14:47] DEBUG[9668][C-00000000] res_musiconhold.c: PJSIP/phone_A-00000000 Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Oct 8 10:14:47] DEBUG[9668][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 8 10:14:48] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:48] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:48] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:49] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:49] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:49] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:49] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:49] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:50] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:50] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:50] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:50] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:51] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:51] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:51] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:52] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:52] DEBUG[9668][C-00000000] app_agent_pool.c: Agent 1001: Login complete. [Oct 8 10:14:52] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:52] DEBUG[9526] devicestate.c: Processing device state change for 'Agent:1001' [Oct 8 10:14:52] DEBUG[9526] devicestate.c: Adding per-server state of 'Not in use' for 'Agent:1001' [Oct 8 10:14:52] DEBUG[9526] devicestate.c: Aggregate devstate result is 'Not in use' for 'Agent:1001' [Oct 8 10:14:52] DEBUG[9526] devicestate.c: Aggregate state for device 'Agent:1001' has changed to 'Not in use' [Oct 8 10:14:52] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:52] DEBUG[9668][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Oct 8 10:14:53] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:53] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:53] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:54] DEBUG[9579] chan_sip.c: Allocating new SIP dialog for 386d43afbe1b-td1bumlsie3r - REGISTER (No RTP) [Oct 8 10:14:54] DEBUG[9579] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Processing device state change for 'SIP/phone_C' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Adding per-server state of 'Not in use' for 'SIP/phone_C' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate devstate result is 'Not in use' for 'SIP/phone_C' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate state for device 'SIP/phone_C' has changed to 'Not in use' [Oct 8 10:14:54] DEBUG[9668][C-00000000] bridge_channel.c: Executing hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:54] DEBUG[9668][C-00000000] bridge_channel.c: Updating interval hook 0xb6f0394c with interval 1000 on 0xb37e819c(PJSIP/phone_A-00000000) [Oct 8 10:14:54] DEBUG[9668][C-00000000] bridge_channel.c: Hook 0xb6f0394c on 0xb37e819c(PJSIP/phone_A-00000000) wants to happen in the future, stopping our traversal [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb2d1e7a4' [Oct 8 10:14:54] DEBUG[9540] res_rtp_asterisk.c: Allocated port 14966 for RTP instance '0xb2d1e7a4' [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: RTP instance '0xb2d1e7a4' is setup and ready to go [Oct 8 10:14:54] DEBUG[9540] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb2d1e7a4' [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 0 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 8 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 9 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 111 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 18 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 58 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 118 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 58 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 96 based on m type on 0xb5d61548 [Oct 8 10:14:54] DEBUG[9669][C-00000001] pbx.c: Launching 'AgentLogin' [Oct 8 10:14:54] VERBOSE[9669][C-00000001] pbx.c: -- Executing [551@internal:1] AgentLogin("PJSIP/phone_B-00000001", "1001") in new stack [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Processing device state change for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9540] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb2d1e7a4' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate state for device 'PJSIP/phone_B' has changed to 'In use' [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 0 based on m type on 0xb5d60fd8 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 8 based on m type on 0xb5d60fd8 [Oct 8 10:14:54] DEBUG[9540] rtp_engine.c: Setting payload 96 based on m type on 0xb5d60fd8 [Oct 8 10:14:54] DEBUG[9669][C-00000001] res_rtp_asterisk.c: 0xb2d22cc0 -- Probation learning mode pass with source address 10.24.18.165:4026 [Oct 8 10:14:54] VERBOSE[9669][C-00000001] app_agent_pool.c: -- Agent '1001' already logged in. [Oct 8 10:14:54] VERBOSE[9669][C-00000001] pbx.c: -- Auto fallthrough, channel 'PJSIP/phone_B-00000001' status is 'UNKNOWN' [Oct 8 10:14:54] DEBUG[9669][C-00000001] channel.c: Soft-Hanging up channel 'PJSIP/phone_B-00000001' [Oct 8 10:14:54] DEBUG[9669][C-00000001] channel.c: Hanging up channel 'PJSIP/phone_B-00000001' [Oct 8 10:14:54] DEBUG[9669][C-00000001] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Oct 8 10:14:54] DEBUG[9530] cdr.c: Finalized CDR for PJSIP/phone_B-00000001 - start 1381245294.163508 answer 1381245294.163888 end 1381245294.374719 dispo ANSWERED [Oct 8 10:14:54] DEBUG[9530] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Processing device state change for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Adding per-server state of 'Not in use' for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate devstate result is 'Not in use' for 'PJSIP/phone_B' [Oct 8 10:14:54] DEBUG[9526] devicestate.c: Aggregate state for device 'PJSIP/phone_B' has changed to 'Not in use' [Oct 8 10:14:54] DEBUG[9530] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Oct 8 10:14:54] DEBUG[9530] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Phone B" <1002>','1002','551','internal','PJSIP/phone_B-00000001','AgentLogin','1001','2013-10-08 10:14:54','2013-10-08 10:14:54','2013-10-08 10:14:54','0','0','ANSWERED','DOCUMENTATION','1381245294.1') [Oct 8 10:14:54] ERROR[9540] astobj2.c: user_data is NULL [Oct 8 10:14:54] ERROR[9540] astobj2.c: FRACK!, Failed assertion 0 (0)