[Feb 22 09:41:30] VERBOSE[5397] config.c: == Parsing '/etc/asterisk/logger.conf': [Feb 22 09:41:30] DEBUG[5397] config.c: Parsing /etc/asterisk/logger.conf [Feb 22 09:41:30] VERBOSE[5397] config.c: == Found [Feb 22 09:41:30] VERBOSE[5397] logger.c: Asterisk Queue Logger restarted [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 2c72db2549d3f07f72a367250407fbe8@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:42:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 5ba7108d389ac4771f9410b221b1f8fe@192.168.203.205:5060 [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 5ba7108d389ac4771f9410b221b1f8fe@192.168.203.205:5060 (Checking To) --From tag as7962c283 --To-tag 581d30b0 [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '5ba7108d389ac4771f9410b221b1f8fe@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:42:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 5ba7108d389ac4771f9410b221b1f8fe@192.168.203.205:5060 [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 41b1b9e56b1847a753b50d1d50d1fa3a@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:43:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 301c041f05698a2a34dac8ad49742fa5@192.168.203.205:5060 [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 301c041f05698a2a34dac8ad49742fa5@192.168.203.205:5060 (Checking To) --From tag as7d6b23e3 --To-tag 1591436d [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '301c041f05698a2a34dac8ad49742fa5@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:43:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 301c041f05698a2a34dac8ad49742fa5@192.168.203.205:5060 [Feb 22 09:43:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:43:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:43:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:43:15] DEBUG[5329] manager.c: Running action 'MailboxStatus' [Feb 22 09:43:15] DEBUG[5329] manager.c: Running action 'MailboxCount' [Feb 22 09:43:56] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:43:56] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 5599ec9747b292475bc44e90657a3273@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:44:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 31df037300694b765bbda9524d044619@192.168.203.205:5060 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 0 [ 72]: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK625ce463;rport [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 3 [ 60]: From: "Unknown" ;tag=as3dcfeef3 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 4 [ 62]: To: [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 5 [ 43]: Contact: [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 6 [ 62]: Call-ID: 31df037300694b765bbda9524d044619@192.168.203.205:5060 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.7.0) [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 9 [ 35]: Date: Wed, 22 Feb 2012 07:44:07 GMT [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 22 09:44:07] VERBOSE[5269] chan_sip.c: Reliably Transmitting (NAT) to 192.168.203.231:58034: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK625ce463;rport Max-Forwards: 70 From: "Unknown" ;tag=as3dcfeef3 To: Contact: Call-ID: 31df037300694b765bbda9524d044619@192.168.203.205:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.7.0) Date: Wed, 22 Feb 2012 07:44:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #73 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:44:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK625ce463;rport=5060 Contact: To: ;tag=0661f017 From: "Unknown";tag=as3dcfeef3 Call-ID: 31df037300694b765bbda9524d044619@192.168.203.205:5060 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 0 <-------------> [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK625ce463;rport=5060 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 2 [ 30]: Contact: [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 3 [ 75]: To: ;tag=0661f017 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 4 [ 59]: From: "Unknown";tag=as3dcfeef3 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 5 [ 62]: Call-ID: 31df037300694b765bbda9524d044619@192.168.203.205:5060 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 6 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 7 [ 23]: Accept: application/sdp [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 22 09:44:07] VERBOSE[5269] chan_sip.c: --- (13 headers 0 lines) --- [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 31df037300694b765bbda9524d044619@192.168.203.205:5060 (Checking To) --From tag as3dcfeef3 --To-tag 0661f017 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '31df037300694b765bbda9524d044619@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:44:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 31df037300694b765bbda9524d044619@192.168.203.205:5060 [Feb 22 09:44:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog '31df037300694b765bbda9524d044619@192.168.203.205:5060' Method: OPTIONS [Feb 22 09:44:26] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:44:26] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:44:56] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:44:56] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:45:01] VERBOSE[5239] asterisk.c: -- Remote UNIX connection [Feb 22 09:45:01] VERBOSE[5401] asterisk.c: -- Remote UNIX connection disconnected [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 78c811fa6cef295544ce564f5b8cf76e@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:45:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 0 [ 72]: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK744b726e;rport [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 3 [ 60]: From: "Unknown" ;tag=as6480b481 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 4 [ 62]: To: [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 5 [ 43]: Contact: [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 6 [ 62]: Call-ID: 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.7.0) [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 9 [ 35]: Date: Wed, 22 Feb 2012 07:45:07 GMT [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 22 09:45:07] VERBOSE[5269] chan_sip.c: Reliably Transmitting (NAT) to 192.168.203.231:58034: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK744b726e;rport Max-Forwards: 70 From: "Unknown" ;tag=as6480b481 To: Contact: Call-ID: 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.7.0) Date: Wed, 22 Feb 2012 07:45:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #76 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:45:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK744b726e;rport=5060 Contact: To: ;tag=ead2dbda From: "Unknown";tag=as6480b481 Call-ID: 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 0 <-------------> [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK744b726e;rport=5060 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 2 [ 30]: Contact: [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 3 [ 75]: To: ;tag=ead2dbda [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 4 [ 59]: From: "Unknown";tag=as6480b481 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 5 [ 62]: Call-ID: 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 6 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 7 [ 23]: Accept: application/sdp [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 22 09:45:07] VERBOSE[5269] chan_sip.c: --- (13 headers 0 lines) --- [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 (Checking To) --From tag as6480b481 --To-tag ead2dbda [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #76 [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:45:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060 [Feb 22 09:45:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog '5392e541587e2d7c4cec59383b282f4a@192.168.203.205:5060' Method: OPTIONS [Feb 22 09:45:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:45:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:45:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:45:15] DEBUG[5329] manager.c: Running action 'MailboxStatus' [Feb 22 09:45:15] DEBUG[5329] manager.c: Running action 'MailboxCount' [Feb 22 09:45:26] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:45:26] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:45:56] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:45:56] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> INVITE sip:210@192.168.203.205 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-61d0054e8a07a9af-1---d8754z-;rport Max-Forwards: 70 Contact: To: "210" From: "ChaniaLS";tag=0f127c79 Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 394 v=0 o=- 12974373976138403 1 IN IP4 10.0.2.15 s=CounterPath X-Lite 4.1 c=IN IP4 10.0.2.15 t=0 0 a=ice-ufrag:24a498 a=ice-pwd:2b989fc604c019e1535d212519236593 m=audio 57954 RTP/AVP 107 0 8 101 a=rtpmap:107 BV32/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=candidate:1 1 UDP 659136 10.0.2.15 57954 typ host a=candidate:1 2 UDP 659134 10.0.2.15 57955 typ host <-------------> [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 0 [ 38]: INVITE sip:210@192.168.203.205 SIP/2.0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-61d0054e8a07a9af-1---d8754z-;rport [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 3 [ 40]: Contact: [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 4 [ 34]: To: "210" [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 5 [ 54]: From: "ChaniaLS";tag=0f127c79 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 6 [ 53]: Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 7 [ 14]: CSeq: 1 INVITE [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 12 [ 19]: Content-Length: 394 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 13 [ 0]: [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 0 [ 3]: v=0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 1 [ 40]: o=- 12974373976138403 1 IN IP4 10.0.2.15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 2 [ 24]: s=CounterPath X-Lite 4.1 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 3 [ 18]: c=IN IP4 10.0.2.15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 5 [ 18]: a=ice-ufrag:24a498 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 6 [ 42]: a=ice-pwd:2b989fc604c019e1535d212519236593 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 7 [ 33]: m=audio 57954 RTP/AVP 107 0 8 101 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 8 [ 23]: a=rtpmap:107 BV32/16000 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 11 [ 10]: a=sendrecv [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 12 [ 51]: a=candidate:1 1 UDP 659136 10.0.2.15 57954 typ host [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 13 [ 51]: a=candidate:1 2 UDP 659134 10.0.2.15 57955 typ host [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: --- (13 headers 14 lines) --- [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: = Looking for Call ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. (Checking From) --From tag 0f127c79 --To-tag [Feb 22 09:46:03] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. - INVITE (No RTP) [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 22 09:46:03] DEBUG[5269] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Feb 22 09:46:03] DEBUG[5269] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 22 09:46:03] DEBUG[5269] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 22 09:46:03] DEBUG[5269] netsock2.c: Splitting '10.0.2.15:26954' into... [Feb 22 09:46:03] DEBUG[5269] netsock2.c: ...host '10.0.2.15' and port '26954'. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Sending to 192.168.203.231:58034 (no NAT) [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Initializing initreq for method INVITE - callid YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Using INVITE request as basis request - YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found peer '550' for '550' from 192.168.203.231:58034 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.203.231:58034 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-61d0054e8a07a9af-1---d8754z-;received=192.168.203.231;rport=58034 From: "ChaniaLS";tag=0f127c79 To: "210";tag=as78968c88 Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 1 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="345dad38" Content-Length: 0 <------------> [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #79 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Scheduling destruction of SIP dialog 'YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ.' in 6400 ms (Method: INVITE) [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> ACK sip:210@192.168.203.205 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-61d0054e8a07a9af-1---d8754z-;rport Max-Forwards: 70 To: "210";tag=as78968c88 From: "ChaniaLS";tag=0f127c79 Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 1 ACK Content-Length: 0 <-------------> [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 0 [ 35]: ACK sip:210@192.168.203.205 SIP/2.0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-61d0054e8a07a9af-1---d8754z-;rport [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 3 [ 49]: To: "210";tag=as78968c88 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 4 [ 54]: From: "ChaniaLS";tag=0f127c79 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 5 [ 53]: Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 6 [ 11]: CSeq: 1 ACK [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: --- (8 headers 0 lines) --- [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: = Looking for Call ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. (Checking From) --From tag 0f127c79 --To-tag as78968c88 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #79 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Stopping retransmission on 'YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ.' of Response 1: Match Found [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> INVITE sip:210@192.168.203.205 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;rport Max-Forwards: 70 Contact: To: "210" From: "ChaniaLS";tag=0f127c79 Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Authorization: Digest username="550",realm="asterisk",nonce="345dad38",uri="sip:210@192.168.203.205",response="f12b6a2ba012d03b41e7c75c527ddfee",algorithm=MD5 Content-Length: 394 v=0 o=- 12974373976138403 1 IN IP4 10.0.2.15 s=CounterPath X-Lite 4.1 c=IN IP4 10.0.2.15 t=0 0 a=ice-ufrag:24a498 a=ice-pwd:2b989fc604c019e1535d212519236593 m=audio 57954 RTP/AVP 107 0 8 101 a=rtpmap:107 BV32/16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=candidate:1 1 UDP 659136 10.0.2.15 57954 typ host a=candidate:1 2 UDP 659134 10.0.2.15 57955 typ host <-------------> [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 0 [ 38]: INVITE sip:210@192.168.203.205 SIP/2.0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;rport [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 3 [ 40]: Contact: [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 4 [ 34]: To: "210" [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 5 [ 54]: From: "ChaniaLS";tag=0f127c79 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 6 [ 53]: Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 7 [ 14]: CSeq: 2 INVITE [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 12 [158]: Authorization: Digest username="550",realm="asterisk",nonce="345dad38",uri="sip:210@192.168.203.205",response="f12b6a2ba012d03b41e7c75c527ddfee",algorithm=MD5 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 13 [ 19]: Content-Length: 394 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Header 14 [ 0]: [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 0 [ 3]: v=0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 1 [ 40]: o=- 12974373976138403 1 IN IP4 10.0.2.15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 2 [ 24]: s=CounterPath X-Lite 4.1 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 3 [ 18]: c=IN IP4 10.0.2.15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 5 [ 18]: a=ice-ufrag:24a498 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 6 [ 42]: a=ice-pwd:2b989fc604c019e1535d212519236593 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 7 [ 33]: m=audio 57954 RTP/AVP 107 0 8 101 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 8 [ 23]: a=rtpmap:107 BV32/16000 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-15 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 11 [ 10]: a=sendrecv [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 12 [ 51]: a=candidate:1 1 UDP 659136 10.0.2.15 57954 typ host [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Body 13 [ 51]: a=candidate:1 2 UDP 659134 10.0.2.15 57955 typ host [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: --- (14 headers 14 lines) --- [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: = Looking for Call ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. (Checking From) --From tag 0f127c79 --To-tag [Feb 22 09:46:03] DEBUG[5269] netsock2.c: Splitting '192.168.203.205' into... [Feb 22 09:46:03] DEBUG[5269] netsock2.c: ...host '192.168.203.205' and port ''. [Feb 22 09:46:03] DEBUG[5269] netsock2.c: Splitting '192.168.203.205' into... [Feb 22 09:46:03] DEBUG[5269] netsock2.c: ...host '192.168.203.205' and port ''. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 22 09:46:03] DEBUG[5269] netsock2.c: Splitting '10.0.2.15:26954' into... [Feb 22 09:46:03] DEBUG[5269] netsock2.c: ...host '10.0.2.15' and port '26954'. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Sending to 192.168.203.231:58034 (NAT) [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Initializing initreq for method INVITE - callid YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Using INVITE request as basis request - YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found peer '550' for '550' from 192.168.203.231:58034 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] DEBUG[5269] res_rtp_asterisk.c: Allocated port 11950 for RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: RTP instance '0x2aaaac03d1e8' is setup and ready to go [Feb 22 09:46:03] DEBUG[5269] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] VERBOSE[5269] netsock2.c: == Using SIP RTP TOS bits 184 [Feb 22 09:46:03] VERBOSE[5269] netsock2.c: == Using SIP RTP CoS mark 5 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Setting NAT on RTP to On [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP o=- 12974373976138403 1 IN IP4 10.0.2.15... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP s=CounterPath X-Lite 4.1... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] netsock2.c: Splitting '10.0.2.15' into... [Feb 22 09:46:03] DEBUG[5269] netsock2.c: ...host '10.0.2.15' and port ''. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP c=IN IP4 10.0.2.15... OK. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP a=ice-ufrag:24a498... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing session-level SDP a=ice-pwd:2b989fc604c019e1535d212519236593... UNSUPPORTED. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found RTP audio format 107 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found RTP audio format 0 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Setting payload 0 based on m type on 0x4244c970 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found RTP audio format 8 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Setting payload 8 based on m type on 0x4244c970 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found RTP audio format 101 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Setting payload 101 based on m type on 0x4244c970 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Unsetting payload 107 on 0x4244c970 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found unknown media description format BV32 for ID 107 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 BV32/16000... UNSUPPORTED. [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Found audio description format telephone-event for ID 101 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=candidate:1 1 UDP 659136 10.0.2.15 57954 typ host... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Processing media-level (audio) SDP a=candidate:1 2 UDP 659134 10.0.2.15 57955 typ host... UNSUPPORTED. [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Incorporating payload 0 on 0x4244c970 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Incorporating payload 8 on 0x4244c970 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Incorporating payload 101 on 0x4244c970 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 22 09:46:03] DEBUG[5269] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Peer audio RTP is at port 10.0.2.15:57954 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Copying payload 0 from 0x4244c970 to 0x2aaaac03d3b0 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Copying payload 8 from 0x4244c970 to 0x2aaaac03d3b0 [Feb 22 09:46:03] DEBUG[5269] rtp_engine.c: Copying payload 101 from 0x4244c970 to 0x2aaaac03d3b0 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Checking SIP call limits for device 550 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Updating call counter for incoming call [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Call from peer '550' is 1 out of 2147483647 [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: Looking for 210 in from-internal (domain 192.168.203.205) [Feb 22 09:46:03] DEBUG[5244] devicestate.c: No provider found, checking channel drivers for SIP - 550 [Feb 22 09:46:03] DEBUG[5244] chan_sip.c: Checking device state for peer 550 [Feb 22 09:46:03] DEBUG[5244] devicestate.c: Changing state for SIP/550 - state 2 (In use) [Feb 22 09:46:03] DEBUG[5244] devicestate.c: device 'SIP/550' state '2' [Feb 22 09:46:03] DEBUG[5287] app_queue.c: Device 'SIP/550' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking if I can find provider for "Custom" - number: DND550 [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider SLA with Custom [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider Meetme with Custom [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider Custom with Custom [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Feb 22 09:46:03] DEBUG[5245] db.c: Unable to find key 'DND550' in family 'CustomDevstate' [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/550-00000002 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 550 CallerIDName: device AccountCode: Exten: 210 Context: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: This channel will not be able to handle video. [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 550 Context: ext-local Hint: SIP/550&Custom:DND550 Status: 1 [Feb 22 09:46:03] DEBUG[5245] app_queue.c: Extension '550@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: build_route: Contact hop: [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: list_route: hop: [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: SIP/550-00000002: New call is still down.... Trying... [Feb 22 09:46:03] VERBOSE[5269] chan_sip.c: <--- Transmitting (NAT) to 192.168.203.231:58034 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;received=192.168.203.231;rport=58034 From: "ChaniaLS";tag=0f127c79 To: "210" Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 2 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Feb 22 09:46:03] DEBUG[5269] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:46:03] DEBUG[5244] devicestate.c: No provider found, checking channel drivers for SIP - 550 [Feb 22 09:46:03] DEBUG[5244] chan_sip.c: Checking device state for peer 550 [Feb 22 09:46:03] DEBUG[5244] devicestate.c: Changing state for SIP/550 - state 2 (In use) [Feb 22 09:46:03] DEBUG[5244] devicestate.c: device 'SIP/550' state '2' [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking if I can find provider for "Custom" - number: DND550 [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider SLA with Custom [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider Meetme with Custom [Feb 22 09:46:03] DEBUG[5287] app_queue.c: Device 'SIP/550' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 22 09:46:03] DEBUG[5245] devicestate.c: Checking provider Custom with Custom [Feb 22 09:46:03] DEBUG[5245] db.c: Unable to find key 'DND550' in family 'CustomDevstate' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:1] Macro("SIP/550-00000002", "user-callerid,SKIPTTL,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: SIPURI Value: sip:550@192.168.203.231:58034 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: SIPDOMAIN Value: 192.168.203.205 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: SIPCALLID Value: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/550-00000002 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 550 CallerIDName: device ConnectedLineNum: ConnectedLineName: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 1 Application: Macro AppData: user-callerid,SKIPTTL, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: SKIPTTL Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG2 Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/550-00000002", "AMPUSER=550") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'CHANNEL' is 'SIP/550-00000002' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/550-00000002", "0?report") in new stack [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/550-00000002", "1?Set(REALCALLERIDNUM=550)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 1 Application: Set AppData: AMPUSER=550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: AMPUSER Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 2 Application: GotoIf AppData: 0?report Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 3 Application: ExecIf AppData: 1?Set(REALCALLERIDNUM=550) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: REALCALLERIDNUM Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/550-00000002", "AMPUSER=550") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 4 Application: Set AppData: AMPUSER=550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: AMPUSER Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Chania-LS Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/550-00000002", "AMPUSERCIDNAME=Chania-LS") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 5 Application: Set AppData: AMPUSERCIDNAME=Chania-LS Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: AMPUSERCIDNAME Value: Chania-LS Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSERCIDNAME' is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/550-00000002", "0?report") in new stack [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 6 Application: GotoIf AppData: 0?report Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '1' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DB_RESULT' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/550-00000002", "AMPUSERCID=550") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 7 Application: Set AppData: AMPUSERCID=550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: AMPUSERCID Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSERCIDNAME' is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSERCID' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/550-00000002", "CALLERID(all)="Chania-LS" <550>") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 8 Application: Set AppData: CALLERID(all)="Chania-LS" <550> Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/550-00000002 CallerIDNum: 550 CallerIDName: Chania-LS Uniqueid: 1329896763.2 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/550-00000002", "0?Set(CHANNEL(language)=)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 9 Application: ExecIf AppData: 0?Set(CHANNEL(language)=) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)}" != ""' len 31) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)})' len 31) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is 'SKIPTTL' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/550-00000002", "1?continue") in new stack [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-user-callerid,s,19) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 10 Application: GotoIf AppData: 1?continue Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:19] Set("SIP/550-00000002", "CALLERID(number)=550") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 19 Application: Set AppData: CALLERID(number)=550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:20] Set("SIP/550-00000002", "CALLERID(name)=Chania-LS") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '"Chania-LS" <550>' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 20 Application: Set AppData: CALLERID(name)=Chania-LS Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/550-00000002", "Using CallerID "Chania-LS" <550>") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-user-callerid Extension: s Priority: 21 Application: NoOp AppData: Using CallerID "Chania-LS" <550> Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:2] NoOp("SIP/550-00000002", "Calling Out Route: To_IDC") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 2 Application: NoOp AppData: Calling Out Route: To_IDC Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:3] Set("SIP/550-00000002", "MOHCLASS=default") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 3 Application: Set AppData: MOHCLASS=default Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MOHCLASS Value: default Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:4] Set("SIP/550-00000002", "_NODEST=") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 4 Application: Set AppData: _NODEST= Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: _NODEST Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:5] Macro("SIP/550-00000002", "record-enable,550,OUT,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 5 Application: Macro AppData: record-enable,550,OUT, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 5 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: 550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG2 Value: OUT Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG3 Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'BLINDTRANSFER' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/550-00000002", "1?check") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-record-enable Extension: s Priority: 1 Application: GotoIf AppData: 1?check Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-record-enable,s,4) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-record-enable:4] ExecIf("SIP/550-00000002", "0?MacroExit()") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'ARG1' (from 'ARG1}"=""' len 4) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-record-enable Extension: s Priority: 4 Application: ExecIf AppData: 0?MacroExit() Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG2' is 'OUT' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-record-enable:5] GotoIf("SIP/550-00000002", "0?Group:OUT") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-record-enable Extension: s Priority: 5 Application: GotoIf AppData: 0?Group:OUT Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-record-enable,s,15) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG2' is 'OUT' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-record-enable:15] GotoIf("SIP/550-00000002", "0?IN") in new stack [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DB(AMPUSER/550/recording)' (from 'DB(AMPUSER/550/recording)}' len 25) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-record-enable Extension: s Priority: 15 Application: GotoIf AppData: 0?IN Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: out=Never|in=Never Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'out=Never|in=Never' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'out=Never' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-record-enable:16] ExecIf("SIP/550-00000002", "1?MacroExit()") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-record-enable Extension: s Priority: 16 Application: ExecIf AppData: 1?MacroExit() Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'EXTEN' is '210' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:6] Macro("SIP/550-00000002", "dialout-trunk,1,210,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 6 Application: Macro AppData: dialout-trunk,1,210, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 6 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG2 Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG3 Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/550-00000002", "DIAL_TRUNK=1") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG3' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] db.c: Unable to find key '550/pinless' in family 'AMPUSER' [Feb 22 09:46:03] DEBUG[5404] func_db.c: DB: AMPUSER/550/pinless not found in database. [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GosubIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/550-00000002", "0?sub-pincheck,s,1") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GosubIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'ARG3' (from 'ARG3}" != ""' len 4) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG3' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DB(AMPUSER/${AMPUSER}/pinless)' (from 'DB(AMPUSER/${AMPUSER}/pinless)}" != "NOPASSWD"' len 30) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'AMPUSER' (from 'AMPUSER}/pinless)' len 7) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] db.c: Unable to find key '550/pinless' in family 'AMPUSER' [Feb 22 09:46:03] DEBUG[5404] func_db.c: DB: AMPUSER/550/pinless not found in database. [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 1 Application: Set AppData: DIAL_TRUNK=1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIAL_TRUNK Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 2 Application: GosubIf AppData: 0?sub-pincheck,s,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTDISABLE_1' is 'off' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/550-00000002", "0?disabletrunk,1") in new stack [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG2' is '210' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/550-00000002", "DIAL_NUMBER=210") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 3 Application: GotoIf AppData: 0?disabletrunk,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 4 Application: Set AppData: DIAL_NUMBER=210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIAL_NUMBER Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_OPTIONS' is 'tr' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/550-00000002", "DIAL_TRUNK_OPTIONS=tr") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/550-00000002", "OUTBOUND_GROUP=OUT_1") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 5 Application: Set AppData: DIAL_TRUNK_OPTIONS=tr Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIAL_TRUNK_OPTIONS Value: tr Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 6 Application: Set AppData: OUTBOUND_GROUP=OUT_1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: OUTBOUND_GROUP Value: OUT_1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTMAXCHANS_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/550-00000002", "1?nomax") in new stack [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,s,9) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'INTRACOMPANYROUTE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/550-00000002", "0?skipoutcid") in new stack [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 7 Application: GotoIf AppData: 1?nomax Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 9 Application: GotoIf AppData: 0?skipoutcid Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNK_OPTIONS' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/550-00000002", "DIAL_TRUNK_OPTIONS=") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/550-00000002", "outbound-callerid,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 10 Application: Set AppData: DIAL_TRUNK_OPTIONS= Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIAL_TRUNK_OPTIONS Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 11 Application: Macro AppData: outbound-callerid,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'CALLINGPRES_SV' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'CALLINGPRES_SV' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/550-00000002", "0?Set(CALLERPRES()=)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: s Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV}" != ""' len 14) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'CALLINGPRES_SV' is NULL [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: macro-dialout-trunk Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 11 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV})' len 14) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'CALLINGPRES_SV' is NULL [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 1 Application: ExecIf AppData: 0?Set(CALLERPRES()=) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/550-00000002", "0?Set(REALCALLERIDNUM=550)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 2 Application: ExecIf AppData: 0?Set(REALCALLERIDNUM=550) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'KEEPCID' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTKEEPCID_1' is 'off' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/550-00000002", "1?normcid") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 3 Application: GotoIf AppData: 1?normcid Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-outbound-callerid,s,6) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DB_RESULT Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/550-00000002", "USEROUTCID=") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 6 Application: Set AppData: USEROUTCID= Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: USEROUTCID Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'REALCALLERIDNUM' is '550' [Feb 22 09:46:03] DEBUG[5404] db.c: Unable to find key '550/emergency_cid' in family 'DEVICE' [Feb 22 09:46:03] DEBUG[5404] func_db.c: DB: DEVICE/550/emergency_cid not found in database. [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/550-00000002", "EMERGENCYCID=") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 7 Application: Set AppData: EMERGENCYCID= Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: EMERGENCYCID Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/550-00000002", "TRUNKOUTCID=") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 8 Application: Set AppData: TRUNKOUTCID= Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: TRUNKOUTCID Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'EMERGENCYROUTE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'EMERGENCYCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/550-00000002", "1?trunkcid") in new stack [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-outbound-callerid,s,12) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 9 Application: GotoIf AppData: 1?trunkcid Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKOUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKOUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/550-00000002", "0?Set(CALLERID(all)=)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 12 Application: ExecIf AppData: 0?Set(CALLERID(all)=) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'LEN(${TRUNKOUTCID})' (from 'LEN(${TRUNKOUTCID})} != 0' len 19) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKOUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKOUTCID' is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'USEROUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'USEROUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/550-00000002", "0?Set(CALLERID(all)=)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'LEN(${USEROUTCID})' (from 'LEN(${USEROUTCID})} != 0' len 18) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 13 Application: ExecIf AppData: 0?Set(CALLERID(all)=) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'USEROUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'USEROUTCID' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKCIDOVERRIDE' is NULL [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKCIDOVERRIDE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/550-00000002", "0?Set(CALLERID(all)=)") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'LEN(${TRUNKCIDOVERRIDE})' (from 'LEN(${TRUNKCIDOVERRIDE})} != 0 | ${LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 24) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE})' len 16) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKCIDOVERRIDE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 28) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' (from 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})})' len 84) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})}=0' len 28) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' len 16) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'TRUNKCIDOVERRIDE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'FORCEDOUTCID_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 14 Application: ExecIf AppData: 0?Set(CALLERID(all)=) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/550-00000002", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outbound-callerid Extension: s Priority: 15 Application: ExecIf AppData: 0?Set(CALLERPRES()=prohib_passed_screen) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'Chania-LS' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Macro [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 6 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'PREFIX_TRUNK_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GosubIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/550-00000002", "0?sub-flp-1,s,1") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GosubIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'PREFIX_TRUNK_${DIAL_TRUNK}' (from 'PREFIX_TRUNK_${DIAL_TRUNK}}" != ""' len 26) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK}' len 10) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'PREFIX_TRUNK_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK},s,1' len 10) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 12 Application: GosubIf AppData: 0?sub-flp-1,s,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTPREFIX_1' is '' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_NUMBER' is '210' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/550-00000002", "OUTNUM=210") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'OUT_1' (from 'OUT_1}' len 5) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUT_1' is 'AMP:OOH323/$OUTNUM$@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 13 Application: Set AppData: OUTNUM=210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'AMP' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/550-00000002", "custom=AMP") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: OUTNUM Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 14 Application: Set AppData: custom=AMP Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: custom Value: AMP Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK_OPTIONS' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'ExecIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/550-00000002", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 15 Application: ExecIf AppData: 0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)) Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: ExecIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS}" != "default"' len 8) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS}" != ""' len 8) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS})${DIAL_TRUNK_OPTIONS})' len 8) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'MOHCLASS' is 'default' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS})' len 18) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK_OPTIONS' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/550-00000002", "dialout-trunk-predial-hook,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 16 Application: Macro AppData: dialout-trunk-predial-hook, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: s Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: macro-dialout-trunk Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 16 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'MacroExit' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/550-00000002", "") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Macro [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'PREDIAL_HOOK_RET' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/550-00000002", "0?bypass,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 2 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk-predial-hook Extension: s Priority: 1 Application: MacroExit AppData: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 6 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 17 Application: GotoIf AppData: 0?bypass,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'custom' is 'AMP' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/550-00000002", "1?customtrunk") in new stack [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,s,22) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'OUT_1' (from 'OUT_1}' len 5) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUT_1' is 'AMP:OOH323/$OUTNUM$@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'AMP:OOH323/' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:22] Set("SIP/550-00000002", "pre_num=AMP:OOH323/") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 18 Application: GotoIf AppData: 1?customtrunk Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 22 Application: Set AppData: pre_num=AMP:OOH323/ Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: pre_num Value: AMP:OOH323/ Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'OUT_1' (from 'OUT_1}' len 5) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUT_1' is 'AMP:OOH323/$OUTNUM$@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is 'OUTNUM' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:23] Set("SIP/550-00000002", "the_num=OUTNUM") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 23 Application: Set AppData: the_num=OUTNUM Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: the_num Value: OUTNUM Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK' is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Evaluating 'OUT_1' (from 'OUT_1}' len 5) [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUT_1' is 'AMP:OOH323/$OUTNUM$@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:24] Set("SIP/550-00000002", "post_num=@192.168.200.252:1720") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 24 Application: Set AppData: post_num=@192.168.200.252:1720 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: post_num Value: @192.168.200.252:1720 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'the_num' is 'OUTNUM' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:25] GotoIf("SIP/550-00000002", "1?outnum:skipoutnum") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 25 Application: GotoIf AppData: 1?outnum:skipoutnum Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,s,26) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTNUM' is '210' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:26] Set("SIP/550-00000002", "the_num=210") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 26 Application: Set AppData: the_num=210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: the_num Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'pre_num' is 'AMP:OOH323/' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'the_num' is '210' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'post_num' is '@192.168.200.252:1720' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIAL_TRUNK_OPTIONS' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Dial' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:27] Dial("SIP/550-00000002", "OOH323/210@192.168.200.252:1720,300,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 27 Application: Dial AppData: OOH323/210@192.168.200.252:1720,300, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIALSTATUS Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIALEDPEERNAME Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ANSWEREDTIME Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaad0002d98' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIALEDTIME Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Allocated port 17734 for RTP instance '0x2aaad0002d98' [Feb 22 09:46:03] DEBUG[5404] rtp_engine.c: RTP instance '0x2aaad0002d98' is setup and ready to go [Feb 22 09:46:03] ERROR[5404] chan_ooh323.c: Call to undefined peer 192.168.200.252:1720[Feb 22 09:46:03] DEBUG[5404] rtp_engine.c: Destroyed RTP instance '0x2aaad0002d98' [Feb 22 09:46:03] WARNING[5404] app_dial.c: Unable to create channel of type 'OOH323' (cause 0 - Unknown) [Feb 22 09:46:03] VERBOSE[5404] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: DIALSTATUS Value: CHANUNAVAIL Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Dial Privilege: call,all SubEvent: End Channel: SIP/550-00000002 UniqueID: 1329896763.2 DialStatus: CHANUNAVAIL [Feb 22 09:46:03] DEBUG[5404] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Dial [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'HANGUPCAUSE' is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:28] NoOp("SIP/550-00000002", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 0") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 28 Application: NoOp AppData: Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Goto' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-dialout-trunk:29] Goto("SIP/550-00000002", "s-CHANUNAVAIL,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s Priority: 29 Application: Goto AppData: s-CHANUNAVAIL,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Goto [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'HANGUPCAUSE' is '0' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'HANGUPCAUSE' is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Function result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("SIP/550-00000002", "RC=0") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s-CHANUNAVAIL Priority: 1 Application: Set AppData: RC=0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: RC Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'RC' is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Goto' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("SIP/550-00000002", "0,1") in new stack [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,0,1) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Goto [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: s-CHANUNAVAIL Priority: 2 Application: Goto AppData: 0,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Goto' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [0@macro-dialout-trunk:1] Goto("SIP/550-00000002", "continue,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: 0 Priority: 1 Application: Goto AppData: continue,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,continue,1) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Goto [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'ARG1' is '1' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'OUTFAIL_1' is '' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [continue@macro-dialout-trunk:1] GotoIf("SIP/550-00000002", "1?noreport") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: continue Priority: 1 Application: GotoIf AppData: 1?noreport Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Goto (macro-dialout-trunk,continue,3) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'HANGUPCAUSE' is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [continue@macro-dialout-trunk:3] NoOp("SIP/550-00000002", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 0 - failing through to other trunks") in new stack [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: continue Priority: 3 Application: NoOp AppData: TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 0 - failing through to other trunks Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'AMPUSER' is '550' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Set' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [continue@macro-dialout-trunk:4] Set("SIP/550-00000002", "CALLERID(number)=550") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-dialout-trunk Extension: continue Priority: 4 Application: Set AppData: CALLERID(number)=550 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: NewCallerid Privilege: call,all Channel: SIP/550-00000002 CallerIDNum: 550 CallerIDName: Chania-LS Uniqueid: 1329896763.2 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Set [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [210@from-internal:7] Macro("SIP/550-00000002", "outisbusy,") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: 210 Priority: 7 Application: Macro AppData: outisbusy, Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: 210 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 7 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: ARG1 Value: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Progress' [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outisbusy:1] Progress("SIP/550-00000002", "") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outisbusy Extension: s Priority: 1 Application: Progress AppData: Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: Setting framing from config on incoming call [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 22 09:46:03] VERBOSE[5404] chan_sip.c: Audio is at 5060 [Feb 22 09:46:03] VERBOSE[5404] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Feb 22 09:46:03] VERBOSE[5404] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Feb 22 09:46:03] VERBOSE[5404] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: -- Done with adding codecs to SDP [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 22 09:46:03] VERBOSE[5404] chan_sip.c: <--- Transmitting (NAT) to 192.168.203.231:58034 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;received=192.168.203.231;rport=58034 From: "ChaniaLS";tag=0f127c79 To: "210";tag=as7cd4d9aa Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 2 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 264 v=0 o=root 356385297 356385297 IN IP4 192.168.203.205 s=Asterisk PBX 1.8.7.0 c=IN IP4 192.168.203.205 t=0 0 m=audio 11950 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Feb 22 09:46:03] DEBUG[5404] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: Progress [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'EMERGENCYROUTE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/550-00000002", "0?emergency,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outisbusy Extension: s Priority: 2 Application: GotoIf AppData: 0?emergency,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Result of 'INTRACOMPANYROUTE' is NULL [Feb 22 09:46:03] DEBUG[5404] pbx.c: Expression result is '0' [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outisbusy:3] GotoIf("SIP/550-00000002", "0?intracompany,1") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outisbusy Extension: s Priority: 3 Application: GotoIf AppData: 0?intracompany,1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Not taking any branch [Feb 22 09:46:03] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] pbx.c: Launching 'Playback' [Feb 22 09:46:03] VERBOSE[5404] pbx.c: -- Executing [s@macro-outisbusy:4] Playback("SIP/550-00000002", "all-circuits-busy-now&pls-try-call-later, noanswer") in new stack [Feb 22 09:46:03] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outisbusy Extension: s Priority: 4 Application: Playback AppData: all-circuits-busy-now&pls-try-call-later, noanswer Uniqueid: 1329896763.2 [Feb 22 09:46:03] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format gsm [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] DEBUG[5404] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 22 09:46:03] VERBOSE[5404] file.c: -- Playing 'all-circuits-busy-now.gsm' (language 'en') [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.203.231:49322 [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:03] DEBUG[5404] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 192.168.203.231:41618 [Feb 22 09:46:05] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:05] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:05] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:05] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format ulaw [Feb 22 09:46:05] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format gsm [Feb 22 09:46:05] DEBUG[5404] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 22 09:46:05] VERBOSE[5404] file.c: -- Playing 'pls-try-call-later.gsm' (language 'en') [Feb 22 09:46:07] DEBUG[5404] res_rtp_asterisk.c: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.203.231:49322 [Feb 22 09:46:07] DEBUG[5404] res_rtp_asterisk.c: Got RTCP report of 176 bytes [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 192.168.203.231:49322 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 32173 SequenceNumberCycles: 0 IAJitter: 13 LastSR: 0.0000000000 DLSR: 0.0000(sec) [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 3648c70960b450fe3cb7553e23ca7961@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:46:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 0 [ 72]: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK7364902d;rport [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 3 [ 60]: From: "Unknown" ;tag=as1e53d06f [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 4 [ 62]: To: [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 5 [ 43]: Contact: [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 6 [ 62]: Call-ID: 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.7.0) [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 9 [ 35]: Date: Wed, 22 Feb 2012 07:46:07 GMT [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: Reliably Transmitting (NAT) to 192.168.203.231:58034: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK7364902d;rport Max-Forwards: 70 From: "Unknown" ;tag=as1e53d06f To: Contact: Call-ID: 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.7.0) Date: Wed, 22 Feb 2012 07:46:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #84 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK7364902d;rport=5060 Contact: To: ;tag=b3703496 From: "Unknown";tag=as1e53d06f Call-ID: 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 0 <-------------> [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK7364902d;rport=5060 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 2 [ 30]: Contact: [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 3 [ 75]: To: ;tag=b3703496 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 4 [ 59]: From: "Unknown";tag=as1e53d06f [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 5 [ 62]: Call-ID: 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 6 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 7 [ 23]: Accept: application/sdp [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: --- (13 headers 0 lines) --- [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 (Checking To) --From tag as1e53d06f --To-tag b3703496 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #84 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060 [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog '14a94cf1379b9b2a07aabc0819ad0168@192.168.203.205:5060' Method: OPTIONS [Feb 22 09:46:07] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:07] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:07] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:07] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format ulaw [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: Playback [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: PLAYBACKSTATUS Value: SUCCESS Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'Congestion' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-outisbusy:5] Congestion("SIP/550-00000002", "20") in new stack [Feb 22 09:46:07] VERBOSE[5404] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.203.231:58034 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;received=192.168.203.231;rport=58034 From: "ChaniaLS";tag=0f127c79 To: "210";tag=as7cd4d9aa Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 2 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-outisbusy Extension: s Priority: 5 Application: Congestion AppData: 20 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #87 [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: Trying to put 'SIP/2.0 503' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: Setting SIP_ALREADYGONE on dialog YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:07] DEBUG[5404] channel.c: Soft-Hanging up channel 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5244] devicestate.c: No provider found, checking channel drivers for SIP - 550 [Feb 22 09:46:07] DEBUG[5244] chan_sip.c: Checking device state for peer 550 [Feb 22 09:46:07] DEBUG[5244] devicestate.c: Changing state for SIP/550 - state 2 (In use) [Feb 22 09:46:07] DEBUG[5244] devicestate.c: device 'SIP/550' state '2' [Feb 22 09:46:07] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format slin [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/550-00000002 ChannelState: 7 ChannelStateDesc: Busy CallerIDNum: 550 CallerIDName: Chania-LS ConnectedLineNum: ConnectedLineName: Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking if I can find provider for "Custom" - number: DND550 [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider SLA with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Meetme with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Custom with Custom [Feb 22 09:46:07] DEBUG[5245] db.c: Unable to find key 'DND550' in family 'CustomDevstate' [Feb 22 09:46:07] DEBUG[5287] app_queue.c: Device 'SIP/550' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 22 09:46:07] DEBUG[5404] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 22 09:46:07] DEBUG[5404] channel.c: Prodding channel 'SIP/550-00000002' [Feb 22 09:46:07] WARNING[5404] channel.c: Prodding channel 'SIP/550-00000002' failed [Feb 22 09:46:07] DEBUG[5404] channel.c: Started silence generator on 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 22 09:46:07] DEBUG[5404] channel.c: Stopped silence generator on 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] channel.c: Set channel SIP/550-00000002 to write format ulaw [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Spawn extension (macro-outisbusy,s,5) exited non-zero on 'SIP/550-00000002' in macro 'outisbusy' [Feb 22 09:46:07] VERBOSE[5404] app_macro.c: == Spawn extension (macro-outisbusy, s, 5) exited non-zero on 'SIP/550-00000002' in macro 'outisbusy' [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Spawn extension (from-internal,210,7) exited non-zero on 'SIP/550-00000002' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: == Spawn extension (from-internal, 210, 7) exited non-zero on 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] channel.c: Soft-Hanging up channel 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'Macro' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [h@from-internal:1] Macro("SIP/550-00000002", "hangupcall") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: from-internal Extension: h Priority: 1 Application: Macro AppData: hangupcall Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_IN_HANGUP Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_EXTEN Value: h Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> ACK sip:210@192.168.203.205 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;rport Max-Forwards: 70 To: "210";tag=as7cd4d9aa From: "ChaniaLS";tag=0f127c79 Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. CSeq: 2 ACK Content-Length: 0 <-------------> [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 0 [ 35]: ACK sip:210@192.168.203.205 SIP/2.0 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/UDP 10.0.2.15:26954;branch=z9hG4bK-d8754z-2859e35f060b74a6-1---d8754z-;rport [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 3 [ 49]: To: "210";tag=as7cd4d9aa [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 4 [ 54]: From: "ChaniaLS";tag=0f127c79 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 5 [ 53]: Call-ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 6 [ 11]: CSeq: 2 ACK [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: --- (8 headers 0 lines) --- [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. (Checking From) --From tag 0f127c79 --To-tag as7cd4d9aa [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Function result is '(null)' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/550-00000002", "1?endmixmoncheck") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 1 Application: GotoIf AppData: 1?endmixmoncheck Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,9) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:9] NoOp("SIP/550-00000002", "End of MIXMON check") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 9 Application: NoOp AppData: End of MIXMON check Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'MEETME_RECORDINGFILE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:10] GotoIf("SIP/550-00000002", "1?nomeetmemon") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 10 Application: GotoIf AppData: 1?nomeetmemon Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,15) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'MEETME_RECORDINGFILE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:15] NoOp("SIP/550-00000002", "MEETME_RECORDINGFILE=") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 15 Application: NoOp AppData: MEETME_RECORDINGFILE= Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'TOUCH_MONITOR_OUTPUT' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:16] GotoIf("SIP/550-00000002", "1?noautomon") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 16 Application: GotoIf AppData: 1?noautomon Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,18) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'TOUCH_MONITOR_OUTPUT' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:18] NoOp("SIP/550-00000002", "TOUCH_MONITOR_OUTPUT=") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 18 Application: NoOp AppData: TOUCH_MONITOR_OUTPUT= Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'MONITOR_FILENAME' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:19] GotoIf("SIP/550-00000002", "1?noautomon2") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 19 Application: GotoIf AppData: 1?noautomon2 Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,25) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'MONITOR_FILENAME' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'NoOp' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:25] NoOp("SIP/550-00000002", "MONITOR_FILENAME=") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 25 Application: NoOp AppData: MONITOR_FILENAME= Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: Noop [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'USE_CONFIRMATION' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'RINGGROUP_INDEX' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'CHANNEL' is 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'UNIQCHAN' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:26] GotoIf("SIP/550-00000002", "1?skiprg") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 26 Application: GotoIf AppData: 1?skiprg Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,29) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'BLKVM_BASE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'BLKVM_BASE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'CHANNEL' is 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'BLKVM_OVERRIDE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:29] GotoIf("SIP/550-00000002", "1?skipblkvm") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 29 Application: GotoIf AppData: 1?skipblkvm Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,32) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'FMGRP' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'FMUNIQUE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'CHANNEL' is 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Result of 'FMUNIQUE' is NULL [Feb 22 09:46:07] DEBUG[5404] pbx.c: Expression result is '1' [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'GotoIf' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:32] GotoIf("SIP/550-00000002", "1?theend") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 32 Application: GotoIf AppData: 1?theend Uniqueid: 1329896763.2 [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Goto (macro-hangupcall,s,34) [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Executed application: GotoIf [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Launching 'Hangup' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: -- Executing [s@macro-hangupcall:34] Hangup("SIP/550-00000002", "") in new stack [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Newexten Privilege: dialplan,all Channel: SIP/550-00000002 Context: macro-hangupcall Extension: s Priority: 34 Application: Hangup AppData: Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] app_macro.c: Spawn extension (macro-hangupcall,s,34) exited non-zero on 'SIP/550-00000002' in macro 'hangupcall' [Feb 22 09:46:07] VERBOSE[5404] app_macro.c: == Spawn extension (macro-hangupcall, s, 34) exited non-zero on 'SIP/550-00000002' in macro 'hangupcall' [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: VarSet Privilege: dialplan,all Channel: SIP/550-00000002 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1329896763.2 [Feb 22 09:46:07] DEBUG[5404] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/550-00000002' [Feb 22 09:46:07] VERBOSE[5404] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] channel.c: Hanging up channel 'SIP/550-00000002' [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: Hanging up zombie call. Be scared. [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: update_call_counter(550) - decrement call limit counter on hangup [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: Updating call counter for incoming call [Feb 22 09:46:07] DEBUG[5404] chan_sip.c: Call from peer '550' removed from call limit 2147483647 [Feb 22 09:46:07] DEBUG[5244] devicestate.c: No provider found, checking channel drivers for SIP - 550 [Feb 22 09:46:07] DEBUG[5244] chan_sip.c: Checking device state for peer 550 [Feb 22 09:46:07] DEBUG[5244] devicestate.c: Changing state for SIP/550 - state 1 (Not in use) [Feb 22 09:46:07] DEBUG[5244] devicestate.c: device 'SIP/550' state '1' [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking if I can find provider for "Custom" - number: DND550 [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider SLA with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Meetme with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Custom with Custom [Feb 22 09:46:07] DEBUG[5245] db.c: Unable to find key 'DND550' in family 'CustomDevstate' [Feb 22 09:46:07] DEBUG[5245] app_queue.c: Extension '550@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 22 09:46:07] DEBUG[5287] app_queue.c: Device 'SIP/550' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 550 Context: ext-local Hint: SIP/550&Custom:DND550 Status: 0 [Feb 22 09:46:07] DEBUG[5404] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #87 [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Stopping retransmission on 'YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ.' of Response 2: Match Found [Feb 22 09:46:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ. [Feb 22 09:46:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog 'YzQ1MzRjNDc0YjZjN2MxYmZkZDBmNmZhZTgyNzRiNGQ.' Method: ACK [Feb 22 09:46:07] DEBUG[5269] rtp_engine.c: Destroyed RTP instance '0x2aaaac03d1e8' [Feb 22 09:46:07] DEBUG[5329] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/550-00000002 Uniqueid: 1329896763.2 CallerIDNum: 550 CallerIDName: Chania-LS ConnectedLineNum: ConnectedLineName: Cause: 16 Cause-txt: Normal Clearing [Feb 22 09:46:07] DEBUG[5244] devicestate.c: No provider found, checking channel drivers for SIP - 550 [Feb 22 09:46:07] DEBUG[5244] chan_sip.c: Checking device state for peer 550 [Feb 22 09:46:07] DEBUG[5244] devicestate.c: Changing state for SIP/550 - state 1 (Not in use) [Feb 22 09:46:07] DEBUG[5244] devicestate.c: device 'SIP/550' state '1' [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking if I can find provider for "Custom" - number: DND550 [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider SLA with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Meetme with Custom [Feb 22 09:46:07] DEBUG[5245] devicestate.c: Checking provider Custom with Custom [Feb 22 09:46:07] DEBUG[5245] db.c: Unable to find key 'DND550' in family 'CustomDevstate' [Feb 22 09:46:07] DEBUG[5287] app_queue.c: Device 'SIP/550' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 22 09:46:19] VERBOSE[5336] asterisk.c: -- Remote UNIX connection disconnected [Feb 22 09:46:26] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:46:26] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:46:56] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:46:56] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 5e80fa4c081752960c7987ca64356e29@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:47:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 0 [ 72]: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK250de96a;rport [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 3 [ 60]: From: "Unknown" ;tag=as3f69677d [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 4 [ 62]: To: [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 5 [ 43]: Contact: [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 6 [ 62]: Call-ID: 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.7.0) [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 9 [ 35]: Date: Wed, 22 Feb 2012 07:47:07 GMT [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 22 09:47:07] VERBOSE[5269] chan_sip.c: Reliably Transmitting (NAT) to 192.168.203.231:58034: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK250de96a;rport Max-Forwards: 70 From: "Unknown" ;tag=as3f69677d To: Contact: Call-ID: 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.7.0) Date: Wed, 22 Feb 2012 07:47:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #88 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:47:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK250de96a;rport=5060 Contact: To: ;tag=7ccf40fe From: "Unknown";tag=as3f69677d Call-ID: 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 0 <-------------> [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK250de96a;rport=5060 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 2 [ 30]: Contact: [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 3 [ 75]: To: ;tag=7ccf40fe [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 4 [ 59]: From: "Unknown";tag=as3f69677d [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 5 [ 62]: Call-ID: 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 6 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 7 [ 23]: Accept: application/sdp [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 22 09:47:07] VERBOSE[5269] chan_sip.c: --- (13 headers 0 lines) --- [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 (Checking To) --From tag as3f69677d --To-tag 7ccf40fe [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88 [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:47:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060 [Feb 22 09:47:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog '7d93130c2aa47a967312cbad3f796410@192.168.203.205:5060' Method: OPTIONS [Feb 22 09:47:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:47:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:47:15] DEBUG[5329] manager.c: Running action 'Command' [Feb 22 09:47:15] DEBUG[5329] manager.c: Running action 'MailboxStatus' [Feb 22 09:47:15] DEBUG[5329] manager.c: Running action 'MailboxCount' [Feb 22 09:47:26] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:47:26] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:47:56] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> <-------------> [Feb 22 09:47:56] DEBUG[5269] chan_sip.c: Header 0 [ 0]: [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Allocating new SIP dialog for 2ed1e6a471d77c04160a07082d379ff7@127.0.0.1:0 - OPTIONS (No RTP) [Feb 22 09:48:07] DEBUG[5269] acl.c: For destination '192.168.203.231', our source address is '192.168.203.205'. [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.203.205:5060 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Initializing initreq for method OPTIONS - callid 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 0 [ 72]: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK08f65d01;rport [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 3 [ 60]: From: "Unknown" ;tag=as1ae896a6 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 4 [ 62]: To: [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 5 [ 43]: Contact: [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 6 [ 62]: Call-ID: 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 8 [ 31]: User-Agent: FPBX-2.8.1(1.8.7.0) [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 9 [ 35]: Date: Wed, 22 Feb 2012 07:48:07 GMT [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 22 09:48:07] VERBOSE[5269] chan_sip.c: Reliably Transmitting (NAT) to 192.168.203.231:58034: OPTIONS sip:550@192.168.203.231:58034;rinstance=597cb6b951062082 SIP/2.0 Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK08f65d01;rport Max-Forwards: 70 From: "Unknown" ;tag=as1ae896a6 To: Contact: Call-ID: 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 CSeq: 102 OPTIONS User-Agent: FPBX-2.8.1(1.8.7.0) Date: Wed, 22 Feb 2012 07:48:07 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #91 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.203.231:58034 [Feb 22 09:48:07] VERBOSE[5269] chan_sip.c: <--- SIP read from UDP:192.168.203.231:58034 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK08f65d01;rport=5060 Contact: To: ;tag=b632f2c8 From: "Unknown";tag=as1ae896a6 Call-ID: 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Supported: replaces User-Agent: X-Lite 4 release 4.1 stamp 63214 Content-Length: 0 <-------------> [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 192.168.203.205:5060;branch=z9hG4bK08f65d01;rport=5060 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 2 [ 30]: Contact: [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 3 [ 75]: To: ;tag=b632f2c8 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 4 [ 59]: From: "Unknown";tag=as1ae896a6 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 5 [ 62]: Call-ID: 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 6 [ 17]: CSeq: 102 OPTIONS [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 7 [ 23]: Accept: application/sdp [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 10 [ 19]: Supported: replaces [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 11 [ 44]: User-Agent: X-Lite 4 release 4.1 stamp 63214 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 22 09:48:07] VERBOSE[5269] chan_sip.c: --- (13 headers 0 lines) --- [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: = Looking for Call ID: 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 (Checking To) --From tag as1ae896a6 --To-tag b632f2c8 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #91 [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Stopping retransmission on '7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060' of Request 102: Match Found [Feb 22 09:48:07] DEBUG[5269] chan_sip.c: Destroying SIP dialog 7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060 [Feb 22 09:48:07] VERBOSE[5269] chan_sip.c: Really destroying SIP dialog '7e06bbed14f7a3031bb4fe025dac1b19@192.168.203.205:5060' Method: OPTIONS