[Nov 1 08:34:40] Asterisk 11.0.0-rc2 built by root @ asterisk on a i686 running Linux on 2012-10-18 08:33:04 UTC [Nov 1 08:34:40] VERBOSE[18633] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Nov 1 08:34:42] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:34:43] DEBUG[2966][C-00000d7e] logger.c: CALL_ID [C-00000d7e] bound to thread. [Nov 1 08:34:43] DEBUG[2966][C-00000d7e] chan_dahdi.c: Echo cancellation already on [Nov 1 08:34:43] VERBOSE[18677][C-00000d7e] app_queue.c: -- DAHDI/i1/5942-dea connected line has changed. Saving it until answer for DAHDI/i1/5036-de9 [Nov 1 08:34:43] VERBOSE[18677][C-00000d7e] app_queue.c: -- DAHDI/i1/5942-dea answered DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[2966][C-00000d7e] logger.c: Call_ID [C-00000d7e] being removed from thread. [Nov 1 08:34:43] DEBUG[2958] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/5942 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Requested indication 22 on channel DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] sig_pri.c: Received AST_CONTROL_CONNECTED_LINE on DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Set option TONE VERIFY, mode: MUTECONF(1) on DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Set option TONE VERIFY, mode: MUTECONF(1) on DAHDI/i1/5942-dea [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Requested indication -1 on channel DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[2958] devicestate.c: Changing state for DAHDI/i1/5942 - state 2 (In use) [Nov 1 08:34:43] DEBUG[2958] devicestate.c: device 'DAHDI/i1/5942' state '2' [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] devicestate.c: device 'Queue:SPP1' state '1' [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] app_queue.c: Queue 'SPP1' Leave, Channel 'DAHDI/i1/5036-de9' [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] features.c: bridge answer set, chan answer set [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] features.c: Removing dialed interfaces datastore on DAHDI/i1/5942-dea since we're bridging [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Requested indication 20 on channel DAHDI/i1/5036-de9 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Requested indication 20 on channel DAHDI/i1/5942-dea [Nov 1 08:34:43] DEBUG[2998] app_queue.c: Device 'DAHDI/i1/5942' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: master: 27, slave: 2, nothingok: 0 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Stopping tones on 27/0(DAHDI/i1/5036-de9) talking to 2/0(DAHDI/i1/5942-dea) [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Stopping tones on 2/0(DAHDI/i1/5942-dea) talking to 27/0(DAHDI/i1/5036-de9) [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Disabled echo cancellation on channel 27 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Disabled echo cancellation on channel 2 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Making 2 slave to master 27 at 0 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Added 14 to conference 9/27 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Added 38 to conference 9/2 [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Updated conferencing on 27, with 0 conference users [Nov 1 08:34:43] DEBUG[2998] app_queue.c: Device 'Queue:SPP1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 1 08:34:43] DEBUG[18677][C-00000d7e] chan_dahdi.c: Updated conferencing on 2, with 0 conference users [Nov 1 08:34:43] VERBOSE[18677][C-00000d7e] chan_dahdi.c: -- Native bridging DAHDI/i1/5036-de9 and DAHDI/i1/5942-dea [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: = Looking for Call ID: b108d238-6ac6ac2e@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:34:45] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for b108d238-6ac6ac2e@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: = Looking for Call ID: b108d238-6ac6ac2e@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:34:45] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:45] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:34:45] DEBUG[2968] chan_sip.c: Destroying SIP dialog b108d238-6ac6ac2e@192.168.105.20 [Nov 1 08:34:47] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:34:48] DEBUG[18610][C-00000d7c] res_rtp_asterisk.c: Got RTCP report of 116 bytes [Nov 1 08:34:49] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9cb1496e-b897cd65@192.168.26.116 (Checking From) --From tag 1234b2faec1a9149o0 --To-tag [Nov 1 08:34:49] DEBUG[2968] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Nov 1 08:34:49] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.26.116:5060 [Nov 1 08:34:51] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:34:51] VERBOSE[18684] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:34:52] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:34:53] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:34:53] VERBOSE[18691] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:34:55] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:34:55] VERBOSE[18700] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: = Looking for Call ID: 6927f1f7-7da07b6c@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:34:55] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for 6927f1f7-7da07b6c@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: = Looking for Call ID: 6927f1f7-7da07b6c@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:34:55] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:34:55] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:34:55] DEBUG[2968] chan_sip.c: Destroying SIP dialog 6927f1f7-7da07b6c@192.168.105.20 [Nov 1 08:34:56] VERBOSE[2964] res_xmpp.c: <--- XMPP received from 'jabber' ---> <-------------> [Nov 1 08:34:56] DEBUG[2964] res_xmpp.c: XML parsing successful [Nov 1 08:34:57] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:34:57] VERBOSE[18706] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:34:57] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:34:58] VERBOSE[2964] res_xmpp.c: <--- XMPP keep alive from 'jabber' ---> [Nov 1 08:34:59] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:34:59] VERBOSE[18712] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:00] DEBUG[18610][C-00000d7c] res_rtp_asterisk.c: Got RTCP report of 116 bytes [Nov 1 08:35:01] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:01] VERBOSE[18719] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:02] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:04] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9cb1496e-b897cd65@192.168.26.116 (Checking From) --From tag 1234b2faec1a9149o0 --To-tag [Nov 1 08:35:04] DEBUG[2968] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Nov 1 08:35:04] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.26.116:5060 [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: = Looking for Call ID: 3335e63a-f5b3dff7@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:05] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for 3335e63a-f5b3dff7@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: = Looking for Call ID: 3335e63a-f5b3dff7@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:35:05] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:05] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:35:05] DEBUG[2968] chan_sip.c: Destroying SIP dialog 3335e63a-f5b3dff7@192.168.105.20 [Nov 1 08:35:07] VERBOSE[2964] res_xmpp.c: <--- XMPP received from 'jabber' ---> <-------------> [Nov 1 08:35:07] DEBUG[2964] res_xmpp.c: XML parsing successful [Nov 1 08:35:07] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:09] DEBUG[2968] chan_sip.c: = Looking for Call ID: 0d6989fc83ae21e9f0503d19c000 (Checking From) --From tag 0d6989fc83ae21e8f0503d19c000 --To-tag as4d0484e9 [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] logger.c: CALL_ID [C-00000d7c] bound to thread. [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] netsock2.c: Splitting '10.2.0.6:5060' into... [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] netsock2.c: ...host '10.2.0.6' and port '5060'. [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] chan_sip.c: Setting SIP_ALREADYGONE on dialog 0d6989fc83ae21e9f0503d19c000 [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb440417c' [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] chan_sip.c: Received bye, issuing owner hangup [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.2.0.6:5060 [Nov 1 08:35:09] DEBUG[2968][C-00000d7c] logger.c: Call_ID [C-00000d7c] being removed from thread. [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] channel.c: Didn't get a frame from channel: SIP/russneft-00000afb [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Requested indication 20 on channel DAHDI/i1/6363-de7 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] channel.c: Bridge stops bridging channels SIP/russneft-00000afb and DAHDI/i1/6363-de7 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] channel.c: Hanging up channel 'DAHDI/i1/6363-de7' [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: dahdi_hangup(DAHDI/i1/6363-de7) [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/i1/6363-de7 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] sig_pri.c: sig_pri_hangup 1 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] sig_pri.c: Channel 'DAHDI/i1/6363-de7' MOH-Event: SIG_PRI_MOH_EVENT_RESET in state SIG_PRI_MOH_STATE_IDLE [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] sig_pri.c: Channel 'DAHDI/i1/6363-de7' MOH-Next-State: $ [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] sig_pri.c: Not yet hungup... Calling hangup with cause 16, and clearing call [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Disabled echo cancellation on channel 1 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/i1/6363-de7 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Updated conferencing on 1, with 0 conference users [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/i1/6363-de7 [Nov 1 08:35:09] VERBOSE[18610][C-00000d7c] chan_dahdi.c: -- Hungup 'DAHDI/i1/6363-de7' [Nov 1 08:35:09] VERBOSE[18610][C-00000d7c] abstract_jb.c: -- fixed jitterbuffer destroyed on channel DAHDI/i1/6363-de7 [Nov 1 08:35:09] DEBUG[2958] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/6363 [Nov 1 08:35:09] DEBUG[2958] devicestate.c: Changing state for DAHDI/i1/6363 - state 0 (Unknown) [Nov 1 08:35:09] DEBUG[2958] devicestate.c: device 'DAHDI/i1/6363' state '0' [Nov 1 08:35:09] DEBUG[2998] app_queue.c: Device 'DAHDI/i1/6363' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] pbx.c: Spawn extension (russneft,526363,2) exited non-zero on 'SIP/russneft-00000afb' [Nov 1 08:35:09] VERBOSE[18610][C-00000d7c] pbx.c: == Spawn extension (russneft, 526363, 2) exited non-zero on 'SIP/russneft-00000afb' [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] channel.c: Soft-Hanging up channel 'SIP/russneft-00000afb' [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] channel.c: Hanging up channel 'SIP/russneft-00000afb' [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] chan_sip.c: Hangup call SIP/russneft-00000afb, SIP callid 0d6989fc83ae21e9f0503d19c000 [Nov 1 08:35:09] DEBUG[18610][C-00000d7c] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb440417c' [Nov 1 08:35:09] DEBUG[2958] devicestate.c: No provider found, checking channel drivers for SIP - russneft [Nov 1 08:35:09] DEBUG[2958] chan_sip.c: Checking device state for peer russneft [Nov 1 08:35:09] DEBUG[2958] devicestate.c: Changing state for SIP/russneft - state 1 (Not in use) [Nov 1 08:35:09] DEBUG[2958] devicestate.c: device 'SIP/russneft' state '1' [Nov 1 08:35:09] DEBUG[2998] app_queue.c: Device 'SIP/russneft' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 3 mastertrunkgroup: 0 logicalspan: 0 result: 3 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/3 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 4 mastertrunkgroup: 0 logicalspan: 0 result: 4 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/4 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 5 mastertrunkgroup: 0 logicalspan: 0 result: 5 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/5 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 6 mastertrunkgroup: 0 logicalspan: 0 result: 6 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/6 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 7 mastertrunkgroup: 0 logicalspan: 0 result: 7 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/7 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 8 mastertrunkgroup: 0 logicalspan: 0 result: 8 [Nov 1 08:35:09] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/8 successfully restarted [Nov 1 08:35:09] DEBUG[2966] sig_pri.c: prioffset: 9 mastertrunkgroup: 0 logicalspan: 0 result: 9 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/9 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 10 mastertrunkgroup: 0 logicalspan: 0 result: 10 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/10 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 11 mastertrunkgroup: 0 logicalspan: 0 result: 11 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/11 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 12 mastertrunkgroup: 0 logicalspan: 0 result: 12 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/12 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 13 mastertrunkgroup: 0 logicalspan: 0 result: 13 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/13 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 14 mastertrunkgroup: 0 logicalspan: 0 result: 14 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/14 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 15 mastertrunkgroup: 0 logicalspan: 0 result: 15 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/15 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 17 mastertrunkgroup: 0 logicalspan: 0 result: 17 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/17 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 18 mastertrunkgroup: 0 logicalspan: 0 result: 18 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/18 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 19 mastertrunkgroup: 0 logicalspan: 0 result: 19 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/19 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 20 mastertrunkgroup: 0 logicalspan: 0 result: 20 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/20 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 21 mastertrunkgroup: 0 logicalspan: 0 result: 21 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/21 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 22 mastertrunkgroup: 0 logicalspan: 0 result: 22 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/22 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 23 mastertrunkgroup: 0 logicalspan: 0 result: 23 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/23 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 24 mastertrunkgroup: 0 logicalspan: 0 result: 24 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/24 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 26 mastertrunkgroup: 0 logicalspan: 0 result: 26 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/26 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 28 mastertrunkgroup: 0 logicalspan: 0 result: 28 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/28 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 29 mastertrunkgroup: 0 logicalspan: 0 result: 29 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/29 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 30 mastertrunkgroup: 0 logicalspan: 0 result: 30 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/30 successfully restarted [Nov 1 08:35:10] DEBUG[2966] sig_pri.c: prioffset: 31 mastertrunkgroup: 0 logicalspan: 0 result: 31 [Nov 1 08:35:10] VERBOSE[2966] sig_pri.c: -- Span 1: Channel 0/31 successfully restarted [Nov 1 08:35:12] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: = Looking for Call ID: 1bf76d85-cc4d8d1a@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:15] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for 1bf76d85-cc4d8d1a@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: = Looking for Call ID: 1bf76d85-cc4d8d1a@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:35:15] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:15] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:35:15] DEBUG[2968] chan_sip.c: Destroying SIP dialog 1bf76d85-cc4d8d1a@192.168.105.20 [Nov 1 08:35:17] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:19] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9cb1496e-b897cd65@192.168.26.116 (Checking From) --From tag 1234b2faec1a9149o0 --To-tag [Nov 1 08:35:19] DEBUG[2968] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Nov 1 08:35:19] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.26.116:5060 [Nov 1 08:35:20] VERBOSE[18633] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:21] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:21] VERBOSE[18727] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:22] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:23] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:23] VERBOSE[18758] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:25] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:25] VERBOSE[18768] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9c06d24b-119d02fd@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:25] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for 9c06d24b-119d02fd@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9c06d24b-119d02fd@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:35:25] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:25] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:35:25] DEBUG[2968] chan_sip.c: Destroying SIP dialog 9c06d24b-119d02fd@192.168.105.20 [Nov 1 08:35:27] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:27] VERBOSE[18776] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:27] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:29] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:29] VERBOSE[18784] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:31] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:31] VERBOSE[18790] asterisk.c: -- Remote UNIX connection disconnected [Nov 1 08:35:32] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:34] DEBUG[2968] chan_sip.c: = Looking for Call ID: 9cb1496e-b897cd65@192.168.26.116 (Checking From) --From tag 1234b2faec1a9149o0 --To-tag [Nov 1 08:35:34] DEBUG[2968] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Nov 1 08:35:34] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.26.116:5060 [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: = Looking for Call ID: d292cedf-dd551373@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:35] DEBUG[2968] acl.c: For destination '192.168.105.20', our source address is '192.168.22.19'. [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.22.19:5060 [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: Allocating new SIP dialog for d292cedf-dd551373@192.168.105.20 - SUBSCRIBE (No RTP) [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:35] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:35] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: build_route: Contact hop: "6051" [Nov 1 08:35:35] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:35] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:35] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: = Looking for Call ID: d292cedf-dd551373@192.168.105.20 (Checking From) --From tag f226782c684f55b3 --To-tag [Nov 1 08:35:36] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:36] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:36] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:36] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Nov 1 08:35:36] DEBUG[2968] netsock2.c: Splitting '192.168.105.20:5060' into... [Nov 1 08:35:36] DEBUG[2968] netsock2.c: ...host '192.168.105.20' and port '5060'. [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: build_route: Retaining previous route: [Nov 1 08:35:36] DEBUG[2968] netsock2.c: Splitting 'asterisk.p98.belkam.com' into... [Nov 1 08:35:36] DEBUG[2968] netsock2.c: ...host 'asterisk.p98.belkam.com' and port ''. [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 192.168.105.20:5060 [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: Received SIP subscribe for unknown event package: missed-call-summary [Nov 1 08:35:36] DEBUG[2968] chan_sip.c: Destroying SIP dialog d292cedf-dd551373@192.168.105.20 [Nov 1 08:35:37] DEBUG[17418][C-00000d75] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 1 08:35:40] VERBOSE[2953] asterisk.c: -- Remote UNIX connection [Nov 1 08:35:41] DEBUG[2968] chan_sip.c: Auto destroying SIP dialog '0d6989fc83ae21e9f0503d19c000' [Nov 1 08:35:41] DEBUG[2968] chan_sip.c: Destroying SIP dialog 0d6989fc83ae21e9f0503d19c000 [Nov 1 08:35:41] DEBUG[2968] rtp_engine.c: Destroyed RTP instance '0xb440417c'