Asterisk Ready. *CLI> Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 3c32afae2981-x19ar1sutys5@192-168-161-106 Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:5542 check_user_full: Setting NAT on RTP to 0 Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '3c32afae2981-x19ar1sutys5@192-168-161-106' of Response 1: Found Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:5542 check_user_full: Setting NAT on RTP to 0 Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:7489 handle_request: Check for res for 6301 Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:1582 update_user_counter: Call from user '6301' is 1 out of 0 Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:4767 build_route: build_route: Contact hop: Jan 6 11:11:49 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '2' Jan 6 11:11:49 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '2' Jan 6 11:11:49 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'AgentCallbackLogin' -- Executing AgentCallbackLogin("SIP/6301-71f3", "6301") in new stack Urgent handler Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:1780 sip_answer: sip_answer(SIP/6301-71f3) Jan 6 11:11:49 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format gsm Jan 6 11:11:49 DEBUG[9911]: rtp.c:1283 ast_rtp_write: Ooh, format changed from unknown to alaw Jan 6 11:11:49 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'agent-pass' (language 'de') Urgent handler Jan 6 11:11:49 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '3c32afae2981-x19ar1sutys5@192-168-161-106' of Response 2: Found Jan 6 11:11:51 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 48 (0), at 192.168.161.106 Jan 6 11:11:51 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:11:51 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format alaw Jan 6 11:11:52 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 48 (0), at 192.168.161.106 Jan 6 11:11:52 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 48 (0), at 192.168.161.106 Jan 6 11:11:52 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 48 (0), at 192.168.161.106 Jan 6 11:11:52 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 35 (#), at 192.168.161.106 Jan 6 11:11:52 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format gsm Jan 6 11:11:52 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'agent-newlocation' (language 'de') Urgent handler Jan 6 11:11:54 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 54 (6), at 192.168.161.106 Jan 6 11:11:54 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:11:54 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format alaw Jan 6 11:11:54 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 51 (3), at 192.168.161.106 Jan 6 11:11:54 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 48 (0), at 192.168.161.106 Jan 6 11:11:55 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 49 (1), at 192.168.161.106 Jan 6 11:11:55 DEBUG[9911]: rtp.c:196 send_dtmf: Sending dtmf: 35 (#), at 192.168.161.106 -- Setting global variable 'AGENTBYCALLERID_6301' to '6301' Jan 6 11:11:55 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format gsm Jan 6 11:11:55 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'agent-loginok' (language 'de') Urgent handler Jan 6 11:11:56 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:11:57 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:11:57 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:11:57 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format alaw Jan 6 11:11:57 DEBUG[9911]: channel.c:1778 ast_set_read_format: Set channel SIP/6301-71f3 to read format alaw Jan 6 11:11:57 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-71f3 to write format alaw == Callback Agent '6301' logged in on 6301 Jan 6 11:11:57 DEBUG[9911]: app_queue.c:346 changethread: Device 'Agent/6301' changed to state '0' Jan 6 11:11:57 DEBUG[9911]: app_queue.c:372 changethread: Device 'Agent/6301' changed to state '0' Urgent handler Jan 6 11:11:57 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Hangup' -- Executing Hangup("SIP/6301-71f3", "") in new stack Jan 6 11:11:57 DEBUG[9911]: pbx.c:1909 ast_pbx_run: Spawn extension (teilnehmer,128,2) exited non-zero on 'SIP/6301-71f3' Jan 6 11:11:57 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'SIP/6301-71f3' Jan 6 11:11:57 DEBUG[9911]: chan_sip.c:1669 sip_hangup: sip_hangup(SIP/6301-71f3) Jan 6 11:11:57 DEBUG[9911]: chan_sip.c:1684 sip_hangup: update_user_counter(6301) - decrement inUse counter Urgent handler Jan 6 11:11:57 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:11:57 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:11:57 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '3c32afae2981-x19ar1sutys5@192-168-161-106' of Request 102: Found Jan 6 11:12:16 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 6qWkuHB5HU2E5Cc5@192.168.161.130 -- Saved useragent "IP PHONE 1" for peer 6303 Jan 6 11:12:26 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6303' changed to state '0' Jan 6 11:12:26 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6303' changed to state '0' Urgent handler Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 4D0103DD-9C86-4DE0-AEE1-6331999D84BD@192.168.161.216 -- Saved useragent "SJLabs-SJphone/1.40.258" for peer 6302 Urgent handler Jan 6 11:12:26 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6302' changed to state '0' Jan 6 11:12:26 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6302' changed to state '0' Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 8431b5a5086e0fab0c32a4335ea15cc6@192.168.161.135 Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:7489 handle_request: Check for res for Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:1555 update_user_counter: is not a local user Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:4767 build_route: build_route: Contact hop: sip:02244876779@192.168.161.135:5060;phone-context=isdngw2;user=phone Jan 6 11:12:26 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/5060' changed to state '4' Jan 6 11:12:26 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/5060' changed to state '4' Jan 6 11:12:26 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Answer' -- Executing Answer("SIP/5060-09d88fc8", "") in new stack Urgent handler Jan 6 11:12:26 DEBUG[9911]: chan_sip.c:1780 sip_answer: sip_answer(SIP/5060-09d88fc8) Jan 6 11:12:26 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'GotoIfTime' -- Executing GotoIfTime("SIP/5060-09d88fc8", "9:00-19:00|mon-fri|*|*?queue|129|1") in new stack Urgent handler -- Goto (queue,129,1) Urgent handler Jan 6 11:12:26 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'SetLanguage' -- Executing SetLanguage("SIP/5060-09d88fc8", "de") in new stack Urgent handler Jan 6 11:12:26 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Playback' -- Executing Playback("SIP/5060-09d88fc8", "gws_welcome_queue") in new stack Urgent handler Jan 6 11:12:26 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format gsm Jan 6 11:12:26 DEBUG[9911]: rtp.c:1283 ast_rtp_write: Ooh, format changed from unknown to alaw Jan 6 11:12:26 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'gws_welcome_queue' (language 'de') Urgent handler Jan 6 11:12:27 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '8431b5a5086e0fab0c32a4335ea15cc6@192.168.161.135' of Response 290401560: Found Jan 6 11:12:27 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:30 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for (null) Jan 6 11:12:30 DEBUG[9911]: chan_sip.c:1273 create_addr: Setting NAT on RTP to 0 Jan 6 11:12:30 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '3ce1c69d771629b9284117605f80f847@192.168.161.18' of Request 102: Found Jan 6 11:12:31 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for (null) Jan 6 11:12:31 DEBUG[9911]: chan_sip.c:1273 create_addr: Setting NAT on RTP to 0 Jan 6 11:12:31 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '43b9800a14ee819f0f3aab215d74b495@192.168.161.18' of Request 102: Found Jan 6 11:12:32 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:36 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:12:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:12:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:12:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw Jan 6 11:12:36 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Queue' -- Executing Queue("SIP/5060-09d88fc8", "gws-wartefeld|n|||900") in new stack Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1954 queue_exec: NO QUEUE_PRIO variable found. Using default. Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1965 queue_exec: queue: gws-wartefeld, options: n, url: , announce: , expires: 1105007256, priority: 0 Jan 6 11:12:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format slin -- Started music on hold, class 'default', on SIP/5060-09d88fc8 Jan 6 11:12:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1131 is_our_turn: It's our turn (SIP/5060-09d88fc8). Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1271 try_calling: SIP/5060-09d88fc8 is trying to call a queue member. Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:12:36 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:12:36 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6303' with metric 0 Jan 6 11:12:36 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6302' with metric 0 Jan 6 11:12:36 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6301' with metric 0 Jan 6 11:12:36 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '2' -- outgoing agentcall, to agent '6301', on 'Local/6301@default-9d28,1' Jan 6 11:12:36 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Dial' -- Executing Dial("Local/6301@default-9d28,2", "SIP/6301|20|tT") in new stack Jan 6 11:12:36 DEBUG[9911]: app_dial.c:557 dial_exec: SIMPLE DIAL (NO URL) Jan 6 11:12:36 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for (null) Urgent handler6 DEBUG[9911]: chan_sip.c:1273 create_addr: -- Called Agent/6301 Urgent handler Setting NAT on RTP to 0 Jan 6 11:12:36 DEBUG[9911]: app_queue.c:837 ring_one: Nobody left to try ringing in queue Jan 6 11:12:36 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '2' Urgent handler Jan 6 11:12:36 DEBUG[9911]: app_dial.c:900 dial_exec: Not copying variable STACK-default-6301-1. Jan 6 11:12:36 DEBUG[9911]: chan_sip.c:1436 sip_call: Outgoing Call for 6301 Jan 6 11:12:36 DEBUG[9911]: chan_sip.c:1582 update_user_counter: Call from user '6301' is 1 out of 0 -- Called 6301 Urgent handler Jan 6 11:12:36 DEBUG[9911]: channel.c:1778 ast_set_read_format: Set channel SIP/6301-2f7d to read format alaw Jan 6 11:12:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel Local/6301@default-9d28,2 to write format alaw Jan 6 11:12:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-2f7d to write format alaw Jan 6 11:12:36 DEBUG[9911]: channel.c:1778 ast_set_read_format: Set channel Local/6301@default-9d28,2 to read format alaw Jan 6 11:12:36 DEBUG[9911]: channel.c:1416 ast_read: Generator got voice, switching to phase locked mode Jan 6 11:12:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:12:36 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found Jan 6 11:12:36 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '2' Jan 6 11:12:36 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '2' -- SIP/6301-2f7d is ringing Urgent handler -- Agent/6301 is ringing Urgent handler Jan 6 11:12:37 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found -- SIP/6301-2f7d is ringing Urgent handler Jan 6 11:12:37 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:38 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found -- SIP/6301-2f7d is ringing Urgent handler Jan 6 11:12:40 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found -- SIP/6301-2f7d is ringing Urgent handler Jan 6 11:12:41 DEBUG[9911]: chan_sip.c:780 __sip_autodestruct: Auto destroying call '6qWkuHB5HU2E5Cc5@192.168.161.130' Jan 6 11:12:41 DEBUG[9911]: chan_sip.c:780 __sip_autodestruct: Auto destroying call '4D0103DD-9C86-4DE0-AEE1-6331999D84BD@192.168.161.216' Jan 6 11:12:42 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:44 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found -- SIP/6301-2f7d is ringing Urgent handler Jan 6 11:12:47 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' Request 102: Found -- SIP/6301-2f7d is ringing Urgent handler -- Nobody picked up in 15000 ms Jan 6 11:12:52 DEBUG[9911]: app_queue.c:1380 try_calling: SIP/5060-09d88fc8: Nobody answered. Jan 6 11:12:52 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Agent/6301' Jan 6 11:12:52 DEBUG[9911]: chan_agent.c:571 agent_hangup: Hangup called for state Down Jan 6 11:12:52 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Local/6301@default-9d28,1' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '2' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '2' Jan 6 11:12:52 DEBUG[9911]: chan_agent.c:598 agent_hangup: Hungup, howlong is 16, autologoff is 0 Jan 6 11:12:52 DEBUG[9911]: app_queue.c:346 changethread: Device 'Agent/6301' changed to state '0' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:372 changethread: Device 'Agent/6301' changed to state '0' Urgent handler Jan 6 11:12:52 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'SIP/6301-2f7d' Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:1669 sip_hangup: sip_hangup(SIP/6301-2f7d) Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:1681 sip_hangup: update_user_counter(6301) - decrement outUse counter Jan 6 11:12:52 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:12:52 DEBUG[9911]: app_dial.c:1192 dial_exec: Exiting with DIALSTATUS=CANCEL. Jan 6 11:12:52 DEBUG[9911]: pbx.c:1909 ast_pbx_run: Spawn extension (default,6301,1) exited non-zero on 'Local/6301@default-9d28,2' Jan 6 11:12:52 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Local/6301@default-9d28,2' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '0' Jan 6 11:12:52 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '0' Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:831 __sip_ack: Acked pending invite 102 Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' of Request 102: Found Jan 6 11:12:52 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '779e42083bb203fc69f007ee20b398bd@192.168.161.18' of Request 102: Found Jan 6 11:12:52 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:12:56 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:12:57 DEBUG[9911]: app_queue.c:1131 is_our_turn: It's our turn (SIP/5060-09d88fc8). Jan 6 11:12:57 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw -- Stopped music on hold on SIP/5060-09d88fc8 Jan 6 11:12:57 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:12:57 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format gsm Jan 6 11:12:57 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'queue-youarenext' (language 'de') Urgent handler Jan 6 11:12:57 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:02 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:03 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:03 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:03 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw -- Told SIP/5060-09d88fc8 in gws-wartefeld their queue position (which was 1) Jan 6 11:13:03 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format gsm Jan 6 11:13:03 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'queue-thankyou' (language 'de') Urgent handler Jan 6 11:13:05 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:05 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:05 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw Jan 6 11:13:05 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format slin -- Started music on hold, class 'default', on SIP/5060-09d88fc8 Jan 6 11:13:05 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals Jan 6 11:13:05 DEBUG[9911]: app_queue.c:1271 try_calling: SIP/5060-09d88fc8 is trying to call a queue member. Jan 6 11:13:05 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:13:05 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:13:05 DEBUG[9911]: app_queue.c:1320 try_calling: Queue with URL=_ Jan 6 11:13:05 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6303' with metric 0 Jan 6 11:13:05 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6302' with metric 0 Jan 6 11:13:05 DEBUG[9911]: app_queue.c:822 ring_one: (Parallel) Trying 'Agent/6301' with metric 0 Jan 6 11:13:05 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '2' -- outgoing agentcall, to agent '6301', on 'Local/6301@default-5e0a,1' Jan 6 11:13:05 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Dial' -- Executing Dial("Local/6301@default-5e0a,2", "SIP/6301|20|tT") in new stack Jan 6 11:13:05 DEBUG[9911]: app_dial.c:557 dial_exec: SIMPLE DIAL (NO URL) Jan 6 11:13:05 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for (null) Jan 6 11:13:05 DEBUG[9911]: chan_sip.c:1273 create_addr: Setting NAT on RTP to 0 Jan 6 11:13:05 DEBUG[9911]: app_dial.c:900 dial_exec: Not copying variable STACK-default-6301-1. Jan 6 11:13:05 DEBUG[9911]: chan_sip.c:1436 sip_call: Outgoing Call for 6301 Jan 6 11:13:05 DEBUG[9911]: chan_sip.c:1582 update_user_counter: Call from user '6301' is 1 out of 0 -- Called Agent/6301 Jan 6 11:13:05 DEBUG[9911]: app_queue.c:837 ring_one: Nobody left to try ringing in queue Jan 6 11:13:05 DEBUG[9911]: channel.c:1416 ast_read: Urgent handler Urgent handler Generator got voice, switching to phase locked mode Jan 6 11:13:05 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:05 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '2' -- Called 6301 Urgent handler Jan 6 11:13:05 DEBUG[9911]: channel.c:1778 ast_set_read_format: Set channel SIP/6301-811c to read format alaw Jan 6 11:13:05 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel Local/6301@default-5e0a,2 to write format alaw Jan 6 11:13:05 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/6301-811c to write format alaw Jan 6 11:13:05 DEBUG[9911]: channel.c:1778 ast_set_read_format: Set channel Local/6301@default-5e0a,2 to read format alaw Jan 6 11:13:05 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found Jan 6 11:13:05 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '2' Jan 6 11:13:05 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '2' -- SIP/6301-811c is ringing Urgent handler -- Agent/6301 is ringing Urgent handler Jan 6 11:13:06 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found -- SIP/6301-811c is ringing Urgent handler Jan 6 11:13:07 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found -- SIP/6301-811c is ringing Urgent handler Jan 6 11:13:07 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:09 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found -- SIP/6301-811c is ringing Urgent handler Jan 6 11:13:12 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:13 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found -- SIP/6301-811c is ringing Urgent handler Jan 6 11:13:16 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:13:17 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:881 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' Request 102: Found -- SIP/6301-811c is ringing Urgent handler -- Nobody picked up in 15000 ms Jan 6 11:13:21 DEBUG[9911]: app_queue.c:1380 try_calling: SIP/5060-09d88fc8: Nobody answered. Jan 6 11:13:21 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Agent/6301' Jan 6 11:13:21 DEBUG[9911]: chan_agent.c:571 agent_hangup: Hangup called for state Down Jan 6 11:13:21 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Local/6301@default-5e0a,1' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '2' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '2' Jan 6 11:13:21 DEBUG[9911]: chan_agent.c:598 agent_hangup: Hungup, howlong is 16, autologoff is 0 Jan 6 11:13:21 DEBUG[9911]: app_queue.c:346 changethread: Device 'Agent/6301' changed to state '0' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:372 changethread: Device 'Agent/6301' changed to state '0' Urgent handler Jan 6 11:13:21 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'SIP/6301-811c' Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:1669 sip_hangup: sip_hangup(SIP/6301-811c) Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:1681 sip_hangup: update_user_counter(6301) - decrement outUse counter Jan 6 11:13:21 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6301' changed to state '0' Jan 6 11:13:21 DEBUG[9911]: app_dial.c:1192 dial_exec: Exiting with DIALSTATUS=CANCEL. Jan 6 11:13:21 DEBUG[9911]: pbx.c:1909 ast_pbx_run: Spawn extension (default,6301,1) exited non-zero on 'Local/6301@default-5e0a,2' Jan 6 11:13:21 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'Local/6301@default-5e0a,2' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:346 changethread: Device 'Local/6301@default' changed to state '0' Jan 6 11:13:21 DEBUG[9911]: app_queue.c:372 changethread: Device 'Local/6301@default' changed to state '0' Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:831 __sip_ack: Acked pending invite 102 Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' of Request 102: Found Jan 6 11:13:21 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '51549f7d02313678620e5b801bdefa5d@192.168.161.18' of Request 102: Found Jan 6 11:13:22 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:26 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 6qWkuHB5HU2E5Cc5@192.168.161.130 -- Exiting on time-out cycle Jan 6 11:13:26 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw -- Stopped music on hold on SIP/5060-09d88fc8 Jan 6 11:13:26 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:26 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'Playback' -- Executing Playback("SIP/5060-09d88fc8", "gws_alle_sprechen") in new stack Jan 6 11:13:26 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format gsm Jan 6 11:13:26 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'gws_alle_sprechen' (language 'de') Urgent handler Jan 6 11:13:26 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/6303' changed to state '0' Jan 6 11:13:26 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/6303' changed to state '0' Jan 6 11:13:27 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:30 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 122008544db127f80216231b1f16e9e8@192.168.161.18 Jan 6 11:13:30 DEBUG[9911]: chan_sip.c:4219 transmit_register: Scheduled a registration timeout # 43 Jan 6 11:13:31 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '122008544db127f80216231b1f16e9e8@192.168.161.18' of Request 104: Found Jan 6 11:13:31 DEBUG[9911]: chan_sip.c:6928 handle_response: Registration successful Jan 6 11:13:31 DEBUG[9911]: chan_sip.c:6930 handle_response: Cancelling timeout 43 Jan 6 11:13:32 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw Jan 6 11:13:36 DEBUG[9911]: pbx.c:1263 pbx_extension_helper: Launching 'VoiceMail' -- Executing VoiceMail("SIP/5060-09d88fc8", "s6320") in new stack Urgent handler Jan 6 11:13:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format gsm Jan 6 11:13:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'beep' (language 'de') Urgent handler Jan 6 11:13:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:36 DEBUG[9911]: channel.c:1165 ast_settimeout: Scheduling timer at 0 sample intervals Jan 6 11:13:36 DEBUG[9911]: channel.c:1745 ast_set_write_format: Set channel SIP/5060-09d88fc8 to write format alaw -- Recording the message Jan 6 11:13:36 DEBUG[9911]: app.c:478 ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/default/6320/INBOX/msg0037, 'wav|gsm' Jan 6 11:13:36 DEBUG[9911]: app.c:495 ast_play_and_record: Recording Formats: sfmts=wav -- x=0, open writing: /var/spool/asterisk/voicemail/default/6320/INBOX/msg0037 format: wav, 0x9d96d08 -- x=1, open writing: /var/spool/asterisk/voicemail/default/6320/INBOX/msg0037 format: gsm, 0x9d3fb78 Urgent handler Jan 6 11:13:36 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:13:37 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for (null) Jan 6 11:13:37 DEBUG[9911]: chan_sip.c:1273 create_addr: Setting NAT on RTP to 0 Jan 6 11:13:37 DEBUG[9911]: chan_sip.c:849 __sip_ack: Stopping retransmission on '3781794e339603e5658479f727ea54c1@192.168.161.18' of Request 102: Found Jan 6 11:13:37 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:41 DEBUG[9911]: chan_sip.c:780 __sip_autodestruct: Auto destroying call '6qWkuHB5HU2E5Cc5@192.168.161.130' Jan 6 11:13:42 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:47 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:52 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:13:56 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 Jan 6 11:13:57 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:14:02 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes Jan 6 11:14:07 DEBUG[9911]: rtp.c:398 ast_rtcp_read: Got RTCP report of 80 bytes -- User hung up Jan 6 11:14:12 DEBUG[9911]: app_voicemail.c:1535 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/6320/INBOX/msg0037', format 'wav', uservm is '2048', global is 2048 Jan 6 11:14:12 WARNING[9911]: app_queue.c:341 changethread: Can't change device '**Unknown**' with no technology! Jan 6 11:14:12 WARNING[9911]: app_queue.c:341 changethread: Can't change device '**Unknown**' with no technology! Urgent handler Jan 6 11:14:13 DEBUG[9911]: app_voicemail.c:1661 sendmail: Sent mail to guido@halpdc.gwsnettech.local with command '/usr/sbin/sendmail -t' Jan 6 11:14:13 DEBUG[9911]: pbx.c:1909 ast_pbx_run: Spawn extension (queue,129,5) exited non-zero on 'SIP/5060-09d88fc8' Jan 6 11:14:13 DEBUG[9911]: channel.c:776 ast_hangup: Hanging up channel 'SIP/5060-09d88fc8' Jan 6 11:14:13 DEBUG[9911]: chan_sip.c:1669 sip_hangup: sip_hangup(SIP/5060-09d88fc8) Jan 6 11:14:13 DEBUG[9911]: chan_sip.c:1684 sip_hangup: update_user_counter() - decrement inUse counter Jan 6 11:14:13 DEBUG[9911]: chan_sip.c:1555 update_user_counter: is not a local user Jan 6 11:14:13 DEBUG[9911]: app_queue.c:346 changethread: Device 'SIP/5060' changed to state '4' Jan 6 11:14:13 DEBUG[9911]: app_queue.c:372 changethread: Device 'SIP/5060' changed to state '4' stopJan 6 11:14:16 DEBUG[9911]: chan_sip.c:2345 sip_alloc: Allocating new SIP call for 01D63BC5-9818-4161-BCC4-1B325676BE68@192.168.161.216 now Beginning asterisk shutdown.... Urgent handler Executing last minute cleanups Urgent handler == Destroying musiconhold processes Urgent handler Jan 6 11:14:19 DEBUG[9911]: res_musiconhold.c:913 ast_moh_destroy: killing 9919! Jan 6 11:14:19 DEBUG[9911]: res_musiconhold.c:921 ast_moh_destroy: mpg123 pid 9919 and child died after 786432 bytes read Jan 6 11:14:19 DEBUG[9911]: res_musiconhold.c:913 ast_moh_destroy: killing 9917! Jan 6 11:14:19 DEBUG[9911]: res_musiconhold.c:921 ast_moh_destroy: mpg123 pid 9917 and child died after 2013696 bytes read Asterisk cleanly ending (0). Urgent handler [root@hallinux2 asterisk]#