[Feb 23 08:22:44] DEBUG[5268] pbx.c: Result of 'filename' is '/var/log/asterisk/myDebugLog.0' [Feb 23 08:22:44] DEBUG[5268] pbx.c: Result of 'filename' is '/var/log/asterisk/fail2ban.0' [Feb 23 08:22:44] VERBOSE[5268] config.c: [Feb 23 08:22:44] == Parsing '/etc/asterisk/logger.conf': [Feb 23 08:22:44] DEBUG[5268] config.c: Parsing /etc/asterisk/logger.conf [Feb 23 08:22:44] VERBOSE[5268] config.c: [Feb 23 08:22:44] == Found [Feb 23 08:22:44] DEBUG[5268] pbx.c: Result of 'filename' is '/var/log/asterisk/queue_log.0' [Feb 23 08:22:44] VERBOSE[5268] logger.c: [Feb 23 08:22:44] Asterisk Queue Logger restarted [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- SIP read from UDP:192.168.250.103:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 1 REGISTER Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad000af-1c0d95a2 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 1 REGISTER [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad000af-1c0d95a2 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 11 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] --- (13 headers 0 lines) --- [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 (Checking From) --From tag 6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 --To-tag [Feb 23 08:24:51] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 - REGISTER (No RTP) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-386d4395-6ad000af-1c0d95a2;received=192.168.250.103;rport=5060 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: ;tag=as6f3a1198 Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 1 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="221d2515" Content-Length: 0 <------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Scheduling destruction of SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' in 32000 ms (Method: REGISTER) [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- SIP read from UDP:192.168.250.103:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 2 REGISTER Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0010f-11275ae8 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Authorization: Digest username="3702",realm="asterisk",nonce="221d2515",uri="sip:192.168.250.200",response="482b31b1973edf2bf68a5bafe9b495b5",algorithm=MD5 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 2 REGISTER [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0010f-11275ae8 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 10 [155]: Authorization: Digest username="3702",realm="asterisk",nonce="221d2515",uri="sip:192.168.250.200",response="482b31b1973edf2bf68a5bafe9b495b5",algorithm=MD5 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 11 [ 40]: Contact: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 12 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] --- (14 headers 0 lines) --- [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 (Checking From) --From tag 6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 --To-tag [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] -- Registered SIP '3702' at 192.168.250.103:5060 [Feb 23 08:24:51] DEBUG[1977] pbx.c: Added extension '3702' priority 1 to sip_autoreg (0xa3efc68) [Feb 23 08:24:51] VERBOSE[1977] pbx.c: [Feb 23 08:24:51] -- Added extension '3702' priority 1 to sip_autoreg [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] > Saved useragent "AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845)" for peer 3702 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-386d4395-6ad0010f-11275ae8;received=192.168.250.103;rport=5060 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: ;tag=as6f3a1198 Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 2 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Thu, 23 Feb 2012 10:24:51 GMT Content-Length: 0 <------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:51] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3702 [Feb 23 08:24:51] DEBUG[1577] chan_sip.c: Checking device state for peer 3702 [Feb 23 08:24:51] DEBUG[1577] devicestate.c: Changing state for SIP/3702 - state 1 (Not in use) [Feb 23 08:24:51] DEBUG[1577] devicestate.c: device 'SIP/3702' state '1' [Feb 23 08:24:51] DEBUG[1993] app_queue.c: Device 'SIP/3702' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Scheduling destruction of SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' in 32000 ms (Method: REGISTER) [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- SIP read from UDP:192.168.250.103:5060 ---> OPTIONS sip:192.168.250.200 SIP/2.0 From: ;tag=6ad8d8-67faa8c0-13c4-50029-386d4395-3e507cff-386d4395 To: Call-ID: 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 CSeq: 1 OPTIONS Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0012b-1b7829e5 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 0 [ 35]: OPTIONS sip:192.168.250.200 SIP/2.0 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad8d8-67faa8c0-13c4-50029-386d4395-3e507cff-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 4 [ 15]: CSeq: 1 OPTIONS [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0012b-1b7829e5 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] --- (10 headers 0 lines) --- [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 (Checking From) --From tag 6ad8d8-67faa8c0-13c4-50029-386d4395-3e507cff-386d4395 --To-tag [Feb 23 08:24:51] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 - OPTIONS (No RTP) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Looking for s in default (domain 192.168.250.200) [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-386d4395-6ad0012b-1b7829e5;received=192.168.250.103;rport=5060 From: ;tag=6ad8d8-67faa8c0-13c4-50029-386d4395-3e507cff-386d4395 To: ;tag=as58f544f0 Call-ID: 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 CSeq: 1 OPTIONS Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Scheduling destruction of SIP dialog '6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395' in 32000 ms (Method: OPTIONS) [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- SIP read from UDP:192.168.250.103:5060 ---> SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 To: Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 CSeq: 1 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad00141-4319a831 Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Content-Length: 0 <-------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 1 [ 94]: From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 1 SUBSCRIBE [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad00141-4319a831 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] --- (12 headers 0 lines) --- [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 (Checking From) --From tag 6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 --To-tag [Feb 23 08:24:51] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 - SUBSCRIBE (No RTP) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Creating new subscription [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: build_route: Contact hop: [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] list_route: hop: [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-386d4395-6ad00141-4319a831;received=192.168.250.103;rport=5060 From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 To: ;tag=as0d1b4b40 Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 CSeq: 1 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1046d2d6" Content-Length: 0 <------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Scheduling destruction of SIP dialog '6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395' in 32000 ms (Method: SUBSCRIBE) [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- SIP read from UDP:192.168.250.103:5060 ---> SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 To: Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 CSeq: 2 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0016c-7838767 Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Authorization: Digest username="3702",realm="asterisk",nonce="1046d2d6",uri="sip:3702@192.168.250.200:5060",response="78ab6de7e85ffc30eb3e9ff73906b820",algorithm=MD5 Content-Length: 0 <-------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 1 [ 94]: From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 2 SUBSCRIBE [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 5 [ 84]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-386d4395-6ad0016c-7838767 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 11 [165]: Authorization: Digest username="3702",realm="asterisk",nonce="1046d2d6",uri="sip:3702@192.168.250.200:5060",response="78ab6de7e85ffc30eb3e9ff73906b820",algorithm=MD5 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] --- (13 headers 0 lines) --- [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 (Checking From) --From tag 6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 --To-tag [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Got a new subscription 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 (possibly with auth) or retransmission [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Creating new subscription [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: build_route: Retaining previous route: [Feb 23 08:24:51] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:24:51] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 404 Not found (no mailbox) Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-386d4395-6ad0016c-7838767;received=192.168.250.103;rport=5060 From: ;tag=6ada78-67faa8c0-13c4-50029-386d4395-ce314fb-386d4395 To: ;tag=as0d1b4b40 Call-ID: 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 CSeq: 2 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:51] NOTICE[1977] chan_sip.c: Received SIP subscribe for peer without mailbox: 3702 [Feb 23 08:24:51] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395 [Feb 23 08:24:51] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:51] Really destroying SIP dialog '6b9e20-67faa8c0-13c4-50029-386d4395-738a9b8d-386d4395' Method: SUBSCRIBE [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] <--- SIP read from UDP:192.168.250.103:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 3 REGISTER Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f4613f4-a9bdf4a8-81ecd49 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Authorization: Digest username="3702",realm="asterisk",nonce="221d2515",uri="sip:192.168.250.200",response="482b31b1973edf2bf68a5bafe9b495b5",algorithm=MD5 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 3 REGISTER [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 5 [ 84]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f4613f4-a9bdf4a8-81ecd49 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 10 [155]: Authorization: Digest username="3702",realm="asterisk",nonce="221d2515",uri="sip:192.168.250.200",response="482b31b1973edf2bf68a5bafe9b495b5",algorithm=MD5 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 11 [ 40]: Contact: [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 12 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] --- (14 headers 0 lines) --- [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 (Checking From) --From tag 6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 --To-tag [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] NOTICE[1977] chan_sip.c: Correct auth, but based on stale nonce received from ';tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395' [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f4613f4-a9bdf4a8-81ecd49;received=192.168.250.103;rport=5060 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: ;tag=as6f3a1198 Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 3 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="23d2671c", stale=true Content-Length: 0 <------------> [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] Scheduling destruction of SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' in 32000 ms (Method: REGISTER) [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] <--- SIP read from UDP:192.168.250.103:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 4 REGISTER Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f4613f4-a9bdf4d3-58d1e5ff Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Authorization: Digest username="3702",realm="asterisk",nonce="23d2671c",uri="sip:192.168.250.200",response="5036996d3a1e5df7712d959bf143f108",algorithm=MD5 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 4 REGISTER [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f4613f4-a9bdf4d3-58d1e5ff [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 10 [155]: Authorization: Digest username="3702",realm="asterisk",nonce="23d2671c",uri="sip:192.168.250.200",response="5036996d3a1e5df7712d959bf143f108",algorithm=MD5 [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 11 [ 40]: Contact: [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 12 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] --- (14 headers 0 lines) --- [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 (Checking From) --From tag 6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 --To-tag [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:24:52] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:24:52] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f4613f4-a9bdf4d3-58d1e5ff;received=192.168.250.103;rport=5060 From: ;tag=6ad598-67faa8c0-13c4-50029-386d4395-34bf7d90-386d4395 To: ;tag=as6f3a1198 Call-ID: 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 CSeq: 4 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Thu, 23 Feb 2012 10:24:52 GMT Content-Length: 0 <------------> [Feb 23 08:24:52] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:24:52] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3702 [Feb 23 08:24:52] DEBUG[1577] chan_sip.c: Checking device state for peer 3702 [Feb 23 08:24:52] DEBUG[1577] devicestate.c: Changing state for SIP/3702 - state 1 (Not in use) [Feb 23 08:24:52] DEBUG[1577] devicestate.c: device 'SIP/3702' state '1' [Feb 23 08:24:52] DEBUG[1993] app_queue.c: Device 'SIP/3702' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 23 08:24:52] VERBOSE[1977] chan_sip.c: [Feb 23 08:24:52] Scheduling destruction of SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' in 32000 ms (Method: REGISTER) [Feb 23 08:25:02] DEBUG[5317] manager.c: Running action 'Login' [Feb 23 08:25:02] VERBOSE[5317] manager.c: [Feb 23 08:25:02] == Manager 'ippbx' logged on from 127.0.0.1 [Feb 23 08:25:02] DEBUG[5317] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5317] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name LIKE ? ORDER BY name [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5317] res_config_odbc.c: Parameter 2 ('queue_name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5317] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5317] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5317] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5317] manager.c: Running action 'Command' [Feb 23 08:25:02] VERBOSE[5317] manager.c: [Feb 23 08:25:02] == Manager 'ippbx' logged off from 127.0.0.1 [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Login' [Feb 23 08:25:02] VERBOSE[5319] manager.c: [Feb 23 08:25:02] == Manager 'ippbx' logged on from 127.0.0.1 [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name LIKE ? ORDER BY name [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'TREINAMENTOS' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'COMERCIAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'SUPORTE' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'FINANCEIRO' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue WHERE name = ? [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_queue_members WHERE interface LIKE ? AND queue_name = ? ORDER BY interface [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 1 ('interface LIKE') = '%' [Feb 23 08:25:02] DEBUG[5319] res_config_odbc.c: Parameter 2 ('queue_name') = 'GLOBAL' [Feb 23 08:25:02] DEBUG[5319] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:02] DEBUG[5319] app_queue.c: No queue_members defined in config extconfig.conf [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] DEBUG[5319] manager.c: Running action 'Command' [Feb 23 08:25:02] VERBOSE[5319] manager.c: [Feb 23 08:25:02] == Manager 'ippbx' logged off from 127.0.0.1 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- SIP read from UDP:192.168.250.201:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 To: Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 CSeq: 1 REGISTER Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be3064-3379ede6 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) Content-Length: 0 <-------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 3 [ 61]: Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 1 REGISTER [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be3064-3379ede6 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 11 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] --- (13 headers 0 lines) --- [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 (Checking From) --From tag 6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 --To-tag [Feb 23 08:25:08] DEBUG[1977] acl.c: For destination '192.168.250.201', our source address is '192.168.250.200'. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 - REGISTER (No RTP) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port '5060'. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Sending to 192.168.250.201:5060 (NAT) [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461404-a9be3064-3379ede6;received=192.168.250.201;rport=5060 From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 To: ;tag=as232ca3a4 Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 CSeq: 1 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="39e3aa51" Content-Length: 0 <------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Scheduling destruction of SIP dialog '6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404' in 32000 ms (Method: REGISTER) [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- SIP read from UDP:192.168.250.201:5060 ---> REGISTER sip:192.168.250.200 SIP/2.0 From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 To: Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 CSeq: 2 REGISTER Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30c9-28baf36c Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Expires: 3600 Authorization: Digest username="3701",realm="asterisk",nonce="39e3aa51",uri="sip:192.168.250.200",response="1a40d30b4f5aaae3c4ac17bc4ee7f983",algorithm=MD5 Contact: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) Content-Length: 0 <-------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 0 [ 36]: REGISTER sip:192.168.250.200 SIP/2.0 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 3 [ 61]: Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 4 [ 16]: CSeq: 2 REGISTER [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30c9-28baf36c [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 10 [155]: Authorization: Digest username="3701",realm="asterisk",nonce="39e3aa51",uri="sip:192.168.250.200",response="1a40d30b4f5aaae3c4ac17bc4ee7f983",algorithm=MD5 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 11 [ 40]: Contact: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 12 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] --- (14 headers 0 lines) --- [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 (Checking From) --From tag 6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 --To-tag [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Initializing initreq for method REGISTER - callid 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port '5060'. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Sending to 192.168.250.201:5060 (NAT) [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] -- Registered SIP '3701' at 192.168.250.201:5060 [Feb 23 08:25:08] DEBUG[1977] pbx.c: Added extension '3701' priority 1 to sip_autoreg (0xa3efc68) [Feb 23 08:25:08] VERBOSE[1977] pbx.c: [Feb 23 08:25:08] -- Added extension '3701' priority 1 to sip_autoreg [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] > Saved useragent "AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657)" for peer 3701 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461404-a9be30c9-28baf36c;received=192.168.250.201;rport=5060 From: ;tag=6ad598-c9faa8c0-13c4-50029-4f461404-68a8bc64-4f461404 To: ;tag=as232ca3a4 Call-ID: 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 CSeq: 2 REGISTER Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Thu, 23 Feb 2012 10:25:08 GMT Content-Length: 0 <------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Scheduling destruction of SIP dialog '6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404' in 32000 ms (Method: REGISTER) [Feb 23 08:25:08] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3701 [Feb 23 08:25:08] DEBUG[1577] chan_sip.c: Checking device state for peer 3701 [Feb 23 08:25:08] DEBUG[1577] devicestate.c: Changing state for SIP/3701 - state 1 (Not in use) [Feb 23 08:25:08] DEBUG[1577] devicestate.c: device 'SIP/3701' state '1' [Feb 23 08:25:08] DEBUG[1993] app_queue.c: Device 'SIP/3701' changed to state '1' (Not in use) [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- SIP read from UDP:192.168.250.201:5060 ---> OPTIONS sip:192.168.250.200 SIP/2.0 From: ;tag=6ad8d8-c9faa8c0-13c4-50029-4f461404-7664f473-4f461404 To: Call-ID: 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 CSeq: 1 OPTIONS Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30e0-104c5e49 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) Content-Length: 0 <-------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 0 [ 35]: OPTIONS sip:192.168.250.200 SIP/2.0 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ad8d8-c9faa8c0-13c4-50029-4f461404-7664f473-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 4 [ 15]: CSeq: 1 OPTIONS [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30e0-104c5e49 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] --- (10 headers 0 lines) --- [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 (Checking From) --From tag 6ad8d8-c9faa8c0-13c4-50029-4f461404-7664f473-4f461404 --To-tag [Feb 23 08:25:08] DEBUG[1977] acl.c: For destination '192.168.250.201', our source address is '192.168.250.200'. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 - OPTIONS (No RTP) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port ''. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Looking for s in default (domain 192.168.250.200) [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461404-a9be30e0-104c5e49;received=192.168.250.201;rport=5060 From: ;tag=6ad8d8-c9faa8c0-13c4-50029-4f461404-7664f473-4f461404 To: ;tag=as7148dec1 Call-ID: 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 CSeq: 1 OPTIONS Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Scheduling destruction of SIP dialog '6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404' in 32000 ms (Method: OPTIONS) [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- SIP read from UDP:192.168.250.201:5060 ---> SUBSCRIBE sip:3701@192.168.250.200 SIP/2.0 From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 To: Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 CSeq: 1 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30f6-426b8515 Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Content-Length: 0 <-------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3701@192.168.250.200 SIP/2.0 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 1 [ 94]: From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 1 SUBSCRIBE [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be30f6-426b8515 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] --- (12 headers 0 lines) --- [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 (Checking From) --From tag 6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 --To-tag [Feb 23 08:25:08] DEBUG[1977] acl.c: For destination '192.168.250.201', our source address is '192.168.250.200'. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 - SUBSCRIBE (No RTP) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Creating new subscription [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port '5060'. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Sending to 192.168.250.201:5060 (NAT) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: build_route: Contact hop: [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] list_route: hop: [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Found peer '3701' for '3701' from 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461404-a9be30f6-426b8515;received=192.168.250.201;rport=5060 From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 To: ;tag=as0589dbbf Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 CSeq: 1 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="624a84c7" Content-Length: 0 <------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Scheduling destruction of SIP dialog '6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404' in 32000 ms (Method: SUBSCRIBE) [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- SIP read from UDP:192.168.250.201:5060 ---> SUBSCRIBE sip:3701@192.168.250.200 SIP/2.0 From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 To: Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 CSeq: 2 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be3121-3de04e8b Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Authorization: Digest username="3701",realm="asterisk",nonce="624a84c7",uri="sip:3701@192.168.250.200:5060",response="904106a63e57904cf38460bd6c6708d4",algorithm=MD5 Content-Length: 0 <-------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3701@192.168.250.200 SIP/2.0 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 1 [ 94]: From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 2 SUBSCRIBE [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461404-a9be3121-3de04e8b [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 11 [165]: Authorization: Digest username="3701",realm="asterisk",nonce="624a84c7",uri="sip:3701@192.168.250.200:5060",response="904106a63e57904cf38460bd6c6708d4",algorithm=MD5 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] --- (13 headers 0 lines) --- [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 (Checking From) --From tag 6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 --To-tag [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Got a new subscription 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 (possibly with auth) or retransmission [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Creating new subscription [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port '5060'. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Sending to 192.168.250.201:5060 (NAT) [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: build_route: Retaining previous route: [Feb 23 08:25:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:25:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Found peer '3701' for '3701' from 192.168.250.201:5060 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 404 Not found (no mailbox) Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461404-a9be3121-3de04e8b;received=192.168.250.201;rport=5060 From: ;tag=6ada78-c9faa8c0-13c4-50029-4f461404-6b886ef-4f461404 To: ;tag=as0589dbbf Call-ID: 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 CSeq: 2 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:25:08] NOTICE[1977] chan_sip.c: Received SIP subscribe for peer without mailbox: 3701 [Feb 23 08:25:08] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404 [Feb 23 08:25:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:08] Really destroying SIP dialog '6b9e20-c9faa8c0-13c4-50029-4f461404-78e11641-4f461404' Method: SUBSCRIBE [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- SIP read from UDP:192.168.250.103:5060 ---> OPTIONS sip:192.168.250.200 SIP/2.0 From: ;tag=6ae298-67faa8c0-13c4-50029-4f46140e-5f89197a-4f46140e To: Call-ID: 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e CSeq: 2 OPTIONS Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be596c-42624444 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 0 [ 35]: OPTIONS sip:192.168.250.200 SIP/2.0 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6ae298-67faa8c0-13c4-50029-4f46140e-5f89197a-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 4 [ 15]: CSeq: 2 OPTIONS [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be596c-42624444 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] --- (10 headers 0 lines) --- [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e (Checking From) --From tag 6ae298-67faa8c0-13c4-50029-4f46140e-5f89197a-4f46140e --To-tag [Feb 23 08:25:18] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e - OPTIONS (No RTP) [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Looking for s in default (domain 192.168.250.200) [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f46140e-a9be596c-42624444;received=192.168.250.103;rport=5060 From: ;tag=6ae298-67faa8c0-13c4-50029-4f46140e-5f89197a-4f46140e To: ;tag=as5f52cc51 Call-ID: 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e CSeq: 2 OPTIONS Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Scheduling destruction of SIP dialog '6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e' in 32000 ms (Method: OPTIONS) [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- SIP read from UDP:192.168.250.103:5060 ---> SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e To: Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e CSeq: 1 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be5973-4942cf70 Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Content-Length: 0 <-------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 1 [ 95]: From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 1 SUBSCRIBE [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be5973-4942cf70 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] --- (12 headers 0 lines) --- [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e (Checking From) --From tag 6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e --To-tag [Feb 23 08:25:18] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e - SUBSCRIBE (No RTP) [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Creating new subscription [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: build_route: Contact hop: [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] list_route: hop: [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f46140e-a9be5973-4942cf70;received=192.168.250.103;rport=5060 From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e To: ;tag=as6363a54f Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e CSeq: 1 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="363dd5af" Content-Length: 0 <------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Scheduling destruction of SIP dialog '6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e' in 32000 ms (Method: SUBSCRIBE) [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- SIP read from UDP:192.168.250.103:5060 ---> SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e To: Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e CSeq: 2 SUBSCRIBE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be59ab-58316396 Expires: 3600 Event: message-summary Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer Contact: Authorization: Digest username="3702",realm="asterisk",nonce="363dd5af",uri="sip:3702@192.168.250.200:5060",response="ae778b20ff32dba889c4f33545ea0f57",algorithm=MD5 Content-Length: 0 <-------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 0 [ 42]: SUBSCRIBE sip:3702@192.168.250.200 SIP/2.0 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 1 [ 95]: From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 2 [ 35]: To: [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 4 [ 17]: CSeq: 2 SUBSCRIBE [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46140e-a9be59ab-58316396 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 6 [ 13]: Expires: 3600 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 7 [ 22]: Event: message-summary [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 9 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 10 [ 40]: Contact: [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 11 [165]: Authorization: Digest username="3702",realm="asterisk",nonce="363dd5af",uri="sip:3702@192.168.250.200:5060",response="ae778b20ff32dba889c4f33545ea0f57",algorithm=MD5 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] --- (13 headers 0 lines) --- [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e (Checking From) --From tag 6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e --To-tag [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Got a new subscription 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e (possibly with auth) or retransmission [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Creating new subscription [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: build_route: Retaining previous route: [Feb 23 08:25:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200:5060' into... [Feb 23 08:25:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 404 Not found (no mailbox) Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f46140e-a9be59ab-58316396;received=192.168.250.103;rport=5060 From: ;tag=6ae438-67faa8c0-13c4-50029-4f46140e-30ad65d6-4f46140e To: ;tag=as6363a54f Call-ID: 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e CSeq: 2 SUBSCRIBE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:18] NOTICE[1977] chan_sip.c: Received SIP subscribe for peer without mailbox: 3702 [Feb 23 08:25:18] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e [Feb 23 08:25:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:18] Really destroying SIP dialog '6ba1f0-67faa8c0-13c4-50029-4f46140e-42d004b8-4f46140e' Method: SUBSCRIBE [Feb 23 08:25:23] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395' [Feb 23 08:25:23] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395 [Feb 23 08:25:23] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:23] Really destroying SIP dialog '6ad8d8-67faa8c0-13c4-50029-386d4395-545f2e8e-386d4395' Method: OPTIONS [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- SIP read from UDP:192.168.250.103:5060 ---> INVITE sip:990@192.168.250.200 SIP/2.0 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6f8f-66da9870 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Contact: Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 306 v=0 o=3702 1329993080 1329993080 IN IP4 192.168.250.103 s=- c=IN IP4 192.168.250.103 t=0 0 m=audio 4000 RTP/AVP 9 8 0 18 101 a=rtpmap:9 G722/16000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 0 [ 38]: INVITE sip:990@192.168.250.200 SIP/2.0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 1 [ 98]: From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 2 [ 29]: To: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6f8f-66da9870 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 9 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 10 [ 35]: Contact: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 11 [ 21]: Session-Expires: 1800 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 12 [ 10]: Min-SE: 90 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 14 [ 19]: Content-Length: 306 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 15 [ 0]: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 0 [ 3]: v=0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 1 [ 51]: o=3702 1329993080 1329993080 IN IP4 192.168.250.103 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 2 [ 3]: s=- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 3 [ 24]: c=IN IP4 192.168.250.103 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 5 [ 33]: m=audio 4000 RTP/AVP 9 8 0 18 101 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 6 [ 21]: a=rtpmap:9 G722/16000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 13 [ 10]: a=sendrecv [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] --- (15 headers 14 lines) --- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 (Checking From) --From tag 6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 --To-tag [Feb 23 08:25:24] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 - INVITE (No RTP) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces,100rel,eventlist,timer,timer" [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Found SIP option: -100rel- [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Matched SIP option: 100rel [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Found SIP option: -eventlist- [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Matched SIP option: eventlist [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Matched SIP option: timer [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 23 08:25:24] DEBUG[1977] sip/reqresp_parser.c: Matched SIP option: timer [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Initializing initreq for method INVITE - callid 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Using INVITE request as basis request - 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- Reliably Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f461414-a9be6f8f-66da9870;received=192.168.250.103;rport=5060 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as7ed187c9 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 1 INVITE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4a03053d" Content-Length: 0 <------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #18 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Scheduling destruction of SIP dialog '6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414' in 32000 ms (Method: INVITE) [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- SIP read from UDP:192.168.250.103:5060 ---> ACK sip:990@192.168.250.200 SIP/2.0 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as7ed187c9 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 1 ACK Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6f8f-66da9870 Max-Forwards: 70 User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Contact: Content-Length: 0 <-------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 0 [ 35]: ACK sip:990@192.168.250.200 SIP/2.0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 1 [ 98]: From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 2 [ 44]: To: ;tag=as7ed187c9 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6f8f-66da9870 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 7 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 8 [ 35]: Contact: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] --- (10 headers 0 lines) --- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 (Checking From) --From tag 6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 --To-tag as7ed187c9 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #18 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Stopping retransmission on '6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414' of Response 1: Match Found [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- SIP read from UDP:192.168.250.103:5060 ---> INVITE sip:990@192.168.250.200 SIP/2.0 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 2 INVITE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6fec-5af97d0e Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Contact: Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200",response="f8b908958b173139a9158b7531c464b1",algorithm=MD5 Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 306 v=0 o=3702 1329993080 1329993080 IN IP4 192.168.250.103 s=- c=IN IP4 192.168.250.103 t=0 0 m=audio 4000 RTP/AVP 9 8 0 18 101 a=rtpmap:9 G722/16000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 0 [ 38]: INVITE sip:990@192.168.250.200 SIP/2.0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 1 [ 98]: From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 2 [ 29]: To: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 4 [ 14]: CSeq: 2 INVITE [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be6fec-5af97d0e [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 9 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 10 [ 35]: Contact: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 11 [159]: Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200",response="f8b908958b173139a9158b7531c464b1",algorithm=MD5 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 12 [ 21]: Session-Expires: 1800 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 13 [ 10]: Min-SE: 90 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 15 [ 19]: Content-Length: 306 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 16 [ 0]: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 0 [ 3]: v=0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 1 [ 51]: o=3702 1329993080 1329993080 IN IP4 192.168.250.103 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 2 [ 3]: s=- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 3 [ 24]: c=IN IP4 192.168.250.103 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 5 [ 33]: m=audio 4000 RTP/AVP 9 8 0 18 101 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 6 [ 21]: a=rtpmap:9 G722/16000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Body 13 [ 10]: a=sendrecv [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] --- (16 headers 14 lines) --- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 (Checking From) --From tag 6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 --To-tag [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Initializing initreq for method INVITE - callid 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Using INVITE request as basis request - 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found peer '3702' for '3702' from 192.168.250.103:5060 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa3e1128' [Feb 23 08:25:24] DEBUG[1977] res_rtp_asterisk.c: Allocated port 15562 for RTP instance '0xa3e1128' [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: RTP instance '0xa3e1128' is setup and ready to go [Feb 23 08:25:24] DEBUG[1977] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa3e1128' [Feb 23 08:25:24] VERBOSE[1977] netsock2.c: [Feb 23 08:25:24] == Using SIP RTP CoS mark 5 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Setting NAT on RTP to Off [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing session-level SDP o=3702 1329993080 1329993080 IN IP4 192.168.250.103... UNSUPPORTED. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.250.103... OK. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found RTP audio format 9 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Setting payload 9 based on m type on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found RTP audio format 8 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Setting payload 8 based on m type on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found RTP audio format 0 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Setting payload 0 based on m type on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found RTP audio format 18 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Setting payload 18 based on m type on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found RTP audio format 101 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Setting payload 101 based on m type on 0xb3f98df0 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Unsetting payload 9 on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found unknown media description format G722 for ID 9 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/16000... UNSUPPORTED. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found audio description format PCMA for ID 8 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found audio description format PCMU for ID 0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found audio description format G729 for ID 18 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Found audio description format telephone-event for ID 101 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Incorporating payload 0 on 0xb3f98df0 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Incorporating payload 8 on 0xb3f98df0 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Incorporating payload 18 on 0xb3f98df0 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Incorporating payload 101 on 0xb3f98df0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Capabilities: us - 0x1008 (alaw|g722), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 23 08:25:24] DEBUG[1977] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa3e1128' [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Peer audio RTP is at port 192.168.250.103:4000 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Copying payload 0 from 0xb3f98df0 to 0xa3e12d4 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Copying payload 8 from 0xb3f98df0 to 0xa3e12d4 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Copying payload 18 from 0xb3f98df0 to 0xa3e12d4 [Feb 23 08:25:24] DEBUG[1977] rtp_engine.c: Copying payload 101 from 0xb3f98df0 to 0xa3e12d4 [Feb 23 08:25:24] DEBUG[1977] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xa3e1128' [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Checking SIP call limits for device 3702 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Updating call counter for incoming call [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:25:24] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:25:24] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Looking for 990 in podeddi (domain 192.168.250.200) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: *** Our native formats are 0x8 (alaw) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: *** Our capabilities are 0x1008 (alaw|g722) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: This channel will not be able to handle video. [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:24] DEBUG[1977] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[1977] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: build_route: Contact hop: [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] list_route: hop: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Incoming INVITE with 'timer' option supported and "Session-Expires" header. [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Session-Expires: 1800 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Received Min-SE: 90 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Session timer started: 20 - 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: SIP/3702-00000000: New call is still down.... Trying... [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f461414-a9be6fec-5af97d0e;received=192.168.250.103;rport=5060 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 2 INVITE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:24] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3702 [Feb 23 08:25:24] DEBUG[1577] chan_sip.c: Checking device state for peer 3702 [Feb 23 08:25:24] DEBUG[1577] devicestate.c: Changing state for SIP/3702 - state 1 (Not in use) [Feb 23 08:25:24] DEBUG[1577] devicestate.c: device 'SIP/3702' state '1' [Feb 23 08:25:24] DEBUG[1993] app_queue.c: Device 'SIP/3702' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '990' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [990@podeddi:1] Goto("SIP/3702-00000000", "ura,s,1") [Feb 23 08:25:24] VERBOSE[5870] pbx.c: [Feb 23 08:25:24] -- Goto (ura,s,1) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [s@ura:1] Answer("SIP/3702-00000000", "") [Feb 23 08:25:24] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3702 [Feb 23 08:25:24] DEBUG[1577] chan_sip.c: Checking device state for peer 3702 [Feb 23 08:25:24] DEBUG[1577] devicestate.c: Changing state for SIP/3702 - state 1 (Not in use) [Feb 23 08:25:24] DEBUG[1577] devicestate.c: device 'SIP/3702' state '1' [Feb 23 08:25:24] DEBUG[1993] app_queue.c: Device 'SIP/3702' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: SIP answering channel: SIP/3702-00000000 [Feb 23 08:25:24] DEBUG[5870] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: Setting framing from config on incoming call [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 23 08:25:24] VERBOSE[5870] chan_sip.c: [Feb 23 08:25:24] Audio is at 15562 [Feb 23 08:25:24] VERBOSE[5870] chan_sip.c: [Feb 23 08:25:24] Adding codec 0x8 (alaw) to SDP [Feb 23 08:25:24] VERBOSE[5870] chan_sip.c: [Feb 23 08:25:24] Adding non-codec 0x1 (telephone-event) to SDP [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: -- Done with adding codecs to SDP [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 23 08:25:24] VERBOSE[5870] chan_sip.c: [Feb 23 08:25:24] <--- Reliably Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f461414-a9be6fec-5af97d0e;received=192.168.250.103;rport=5060 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as1cd17590 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 2 INVITE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 1407990615 1407990615 IN IP4 192.168.250.200 s=Asterisk PBX 1.8.9.2 c=IN IP4 192.168.250.200 t=0 0 m=audio 15562 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #22 [Feb 23 08:25:24] DEBUG[5870] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] <--- SIP read from UDP:192.168.250.103:5060 ---> ACK sip:990@192.168.250.200:5060 SIP/2.0 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as1cd17590 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 2 ACK Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be7056-280bc248 Max-Forwards: 70 User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Contact: Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200",response="f8b908958b173139a9158b7531c464b1",algorithm=MD5 Content-Length: 0 <-------------> [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 0 [ 40]: ACK sip:990@192.168.250.200:5060 SIP/2.0 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 1 [ 98]: From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 2 [ 44]: To: ;tag=as1cd17590 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 4 [ 11]: CSeq: 2 ACK [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f461414-a9be7056-280bc248 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 7 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 8 [ 35]: Contact: [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 9 [159]: Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200",response="f8b908958b173139a9158b7531c464b1",algorithm=MD5 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] --- (11 headers 0 lines) --- [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 (Checking From) --From tag 6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 --To-tag as1cd17590 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22 [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Stopping retransmission on '6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414' of Response 2: Match Found [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [s@ura:2] Set("SIP/3702-00000000", "TENTATIVAS=1") [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '3' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '3' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [s@ura:3] Set("SIP/3702-00000000", "TIMEOUT(digit=0)") [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '4' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '4' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [s@ura:4] Set("SIP/3702-00000000", "TIMEOUT(response=2)") [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '5' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:24] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '5' [Feb 23 08:25:24] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:24] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:24] -- Executing [s@ura:5] Wait("SIP/3702-00000000", "1") [Feb 23 08:25:24] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format slin [Feb 23 08:25:24] DEBUG[5870] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 23 08:25:24] DEBUG[5870] channel.c: Started silence generator on 'SIP/3702-00000000' [Feb 23 08:25:24] DEBUG[5870] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Feb 23 08:25:24] DEBUG[5870] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Feb 23 08:25:24] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' [Feb 23 08:25:24] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395 [Feb 23 08:25:24] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:24] Really destroying SIP dialog '6bfa30-67faa8c0-13c4-50029-386d4395-750634d2-386d4395' Method: REGISTER [Feb 23 08:25:25] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:25] DEBUG[5870] channel.c: Stopped silence generator on 'SIP/3702-00000000' [Feb 23 08:25:25] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format alaw [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '6' [Feb 23 08:25:25] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:25] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '6' [Feb 23 08:25:25] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:25] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:25] -- Executing [s@ura:6] ExecIfTime("SIP/3702-00000000", "00:00-11:59,*,*,*?PlayBack(bomdia)") [Feb 23 08:25:25] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format slin [Feb 23 08:25:25] DEBUG[5870] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 23 08:25:25] VERBOSE[5870] file.c: [Feb 23 08:25:25] -- Playing 'bomdia.slin' (language 'pt_BR') [Feb 23 08:25:26] DEBUG[5870] channel.c: Scheduling timer at (76 requested / 76 actual) timer ticks per second [Feb 23 08:25:26] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:26] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:26] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:26] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format alaw [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '7' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '7' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:26] -- Executing [s@ura:7] ExecIfTime("SIP/3702-00000000", "12:00-17:59,*,*,*?PlayBack(boatarde)") [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '8' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '8' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:26] -- Executing [s@ura:8] ExecIfTime("SIP/3702-00000000", "18:00-23:59,*,*,*?PlayBack(boanoite)") [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '9' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:26] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '9' [Feb 23 08:25:26] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:26] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:26] -- Executing [s@ura:9] Wait("SIP/3702-00000000", "1") [Feb 23 08:25:26] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format slin [Feb 23 08:25:26] DEBUG[5870] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 23 08:25:26] DEBUG[5870] channel.c: Started silence generator on 'SIP/3702-00000000' [Feb 23 08:25:27] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:27] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:27] DEBUG[5870] channel.c: Stopped silence generator on 'SIP/3702-00000000' [Feb 23 08:25:27] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format alaw [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '10' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '10' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:27] -- Executing [s@ura:10] ExecIfTime("SIP/3702-00000000", "00:00-23:59,sat-sun,*,*?PlayBack(ipbx/horario)") [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '11' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '11' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:27] -- Executing [s@ura:11] ExecIfTime("SIP/3702-00000000", "00:00-23:59,sat-sun,*,*?AELSub(desliga)") [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '12' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:27] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '12' [Feb 23 08:25:27] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:27] VERBOSE[5870] pbx_realtime.c: [Feb 23 08:25:27] -- Executing [s@ura:12] BackGround("SIP/3702-00000000", "ipbx/a") [Feb 23 08:25:27] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format slin [Feb 23 08:25:27] DEBUG[5870] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 23 08:25:27] VERBOSE[5870] file.c: [Feb 23 08:25:27] -- Playing 'ipbx/a.slin' (language 'pt_BR') [Feb 23 08:25:30] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:36] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:40] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404' [Feb 23 08:25:40] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404 [Feb 23 08:25:40] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:40] Really destroying SIP dialog '6bfa30-c9faa8c0-13c4-50029-4f461404-7136e66-4f461404' Method: REGISTER [Feb 23 08:25:40] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404' [Feb 23 08:25:40] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404 [Feb 23 08:25:40] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:40] Really destroying SIP dialog '6ad8d8-c9faa8c0-13c4-50029-4f461404-68edcb52-4f461404' Method: OPTIONS [Feb 23 08:25:41] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:46] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:47] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:47] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:47] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:25:47] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format alaw [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '13' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 's' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:47] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:47] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:50] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e' [Feb 23 08:25:50] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e [Feb 23 08:25:50] VERBOSE[1977] chan_sip.c: [Feb 23 08:25:50] Really destroying SIP dialog '6ae298-67faa8c0-13c4-50029-4f46140e-563cd415-4f46140e' Method: OPTIONS [Feb 23 08:25:53] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = '' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:25:57] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:25:57] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:25:57] VERBOSE[5870] pbx.c: [Feb 23 08:25:57] -- Timeout on SIP/3702-00000000 [Feb 23 08:25:57] VERBOSE[5870] pbx.c: [Feb 23 08:25:57] == CDR updated on SIP/3702-00000000 [Feb 23 08:25:57] DEBUG[5870] pbx.c: Launching 'Playback' [Feb 23 08:25:57] VERBOSE[5870] pbx.c: [Feb 23 08:25:57] -- Executing [t@ura:1] Playback("SIP/3702-00000000", "tt-monkeys") in new stack [Feb 23 08:25:57] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format gsm [Feb 23 08:25:57] DEBUG[5870] res_rtp_asterisk.c: Difference is 82312, ms is 10309 [Feb 23 08:25:57] DEBUG[5870] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 23 08:25:57] VERBOSE[5870] file.c: [Feb 23 08:25:57] -- Playing 'tt-monkeys.gsm' (language 'pt_BR') [Feb 23 08:26:00] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:26:07] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:26:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:08] <--- SIP read from UDP:192.168.250.201:5060 ---> OPTIONS sip:192.168.250.200 SIP/2.0 From: ;tag=6addb8-c9faa8c0-13c4-50029-4f461440-456b62d6-4f461440 To: Call-ID: 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 CSeq: 2 OPTIONS Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461440-a9bf1b4d-2f3d8870 Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) Content-Length: 0 <-------------> [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 0 [ 35]: OPTIONS sip:192.168.250.200 SIP/2.0 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6addb8-c9faa8c0-13c4-50029-4f461440-456b62d6-4f461440 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 4 [ 15]: CSeq: 2 OPTIONS [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.201:5060;rport;branch=z9hG4bK-4f461440-a9bf1b4d-2f3d8870 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A657) [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:26:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:08] --- (10 headers 0 lines) --- [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 (Checking From) --From tag 6addb8-c9faa8c0-13c4-50029-4f461440-456b62d6-4f461440 --To-tag [Feb 23 08:26:08] DEBUG[1977] acl.c: For destination '192.168.250.201', our source address is '192.168.250.200'. [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 - OPTIONS (No RTP) [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 23 08:26:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:26:08] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:26:08] DEBUG[1977] netsock2.c: Splitting '192.168.250.201' into... [Feb 23 08:26:08] DEBUG[1977] netsock2.c: ...host '192.168.250.201' and port ''. [Feb 23 08:26:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:08] Looking for s in default (domain 192.168.250.200) [Feb 23 08:26:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:08] <--- Transmitting (NAT) to 192.168.250.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.201:5060;branch=z9hG4bK-4f461440-a9bf1b4d-2f3d8870;received=192.168.250.201;rport=5060 From: ;tag=6addb8-c9faa8c0-13c4-50029-4f461440-456b62d6-4f461440 To: ;tag=as6e7ff9dd Call-ID: 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 CSeq: 2 OPTIONS Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 23 08:26:08] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.201:5060 [Feb 23 08:26:08] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:08] Scheduling destruction of SIP dialog '6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440' in 32000 ms (Method: OPTIONS) [Feb 23 08:26:12] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:26:14] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:26:14] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:26:14] DEBUG[5870] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 23 08:26:14] DEBUG[5870] channel.c: Set channel SIP/3702-00000000 to write format alaw [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 't' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:26:14] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '2' [Feb 23 08:26:14] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:14] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Feb 23 08:26:17] DEBUG[5870] res_rtp_asterisk.c: Got RTCP report of 40 bytes [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] <--- SIP read from UDP:192.168.250.103:5060 ---> BYE sip:990@192.168.250.200:5060 SIP/2.0 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as1cd17590 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 3 BYE Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46144a-a9bf411c-5512abee Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200:5060",response="90e9899581dbd1b451046320062e1cf1",algorithm=MD5 Content-Length: 0 <-------------> [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 0 [ 40]: BYE sip:990@192.168.250.200:5060 SIP/2.0 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 1 [ 98]: From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 2 [ 44]: To: ;tag=as1cd17590 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 3 [ 62]: Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 4 [ 11]: CSeq: 3 BYE [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46144a-a9bf411c-5512abee [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 9 [164]: Authorization: Digest username="3702",realm="asterisk",nonce="4a03053d",uri="sip:990@192.168.250.200:5060",response="90e9899581dbd1b451046320062e1cf1",algorithm=MD5 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] --- (11 headers 0 lines) --- [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 (Checking From) --From tag 6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 --To-tag as1cd17590 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Initializing initreq for method BYE - callid 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:26:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.103:5060' into... [Feb 23 08:26:18] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port '5060'. [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] Sending to 192.168.250.103:5060 (NAT) [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:26:18] DEBUG[1977] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa3e1128' [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Session timer stopped: 20 - 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] Scheduling destruction of SIP dialog '6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414' in 32000 ms (Method: BYE) [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Received bye, issuing owner hangup [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f46144a-a9bf411c-5512abee;received=192.168.250.103;rport=5060 From: "Keller";tag=6ae778-67faa8c0-13c4-50029-4f461414-7cb5bd23-4f461414 To: ;tag=as1cd17590 Call-ID: 6ba3d8-67faa8c0-13c4-50029-4f461414-3fa6ba2d-4f461414 CSeq: 3 BYE Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:26:18] WARNING[5870] pbx.c: Don't know what to do with 'SIP/3702-00000000' [Feb 23 08:26:18] DEBUG[5870] channel.c: Soft-Hanging up channel 'SIP/3702-00000000' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ura' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'abreviados' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'programacao' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'uras' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'filas' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'conferencias' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'ramais' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'poderamal' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten = ? AND context = ? AND priority = ? [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten') = 'h' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ast_extensions WHERE exten LIKE ? AND context = ? AND priority = ? ORDER BY exten [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 2 ('context') = 'servicos' [Feb 23 08:26:18] DEBUG[5870] res_config_odbc.c: Parameter 3 ('priority') = '1' [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] channel.c: Hanging up channel 'SIP/3702-00000000' [Feb 23 08:26:18] DEBUG[5870] chan_sip.c: Hanging up zombie call. Be scared. [Feb 23 08:26:18] DEBUG[5870] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa3e1128' [Feb 23 08:26:18] VERBOSE[5870] cdr_adaptive_odbc.c: [Feb 23 08:26:18] > [INSERT INTO ast_cdr (calldate,src,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES ({ ts '2012-02-23 08:25:24' },'3702','t','ura','SIP/3702-00000000','Playback','tt-monkeys',54,54,'ANSWERED',3,'1329992724.0')] [Feb 23 08:26:18] DEBUG[5870] res_odbc.c: odbc_release_obj2(0x9f89ab0) called (obj->txf = (nil)) [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: id INTEGER [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: clid VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: src VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: dst VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: dcontext VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: channel VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: dstchannel VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: lastapp VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: lastdata VARCHAR(80) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: start DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: answer DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: end DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: duration INT(11) NOT NULL DEFAULT 0 [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: billsec INT(11) NOT NULL DEFAULT 0 [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: disposition VARCHAR(45) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: amaflags INT(11) NOT NULL DEFAULT 0 [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: accountcode VARCHAR(20) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: uniqueid VARCHAR(32) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: userfield VARCHAR(255) NOT NULL DEFAULT '' [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: Found field: PRIMARY KEY (id) [Feb 23 08:26:18] DEBUG[5870] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"Keller" <3702>','3702','t','ura','SIP/3702-00000000','Playback','tt-monkeys','2012-02-23 08:25:24','2012-02-23 08:25:24','2012-02-23 08:26:18','54','54','ANSWERED','DOCUMENTATION','1329992724.0') [Feb 23 08:26:18] DEBUG[1577] devicestate.c: No provider found, checking channel drivers for SIP - 3702 [Feb 23 08:26:18] DEBUG[1577] chan_sip.c: Checking device state for peer 3702 [Feb 23 08:26:18] DEBUG[1577] devicestate.c: Changing state for SIP/3702 - state 1 (Not in use) [Feb 23 08:26:18] DEBUG[1577] devicestate.c: device 'SIP/3702' state '1' [Feb 23 08:26:18] DEBUG[1993] app_queue.c: Device 'SIP/3702' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] <--- SIP read from UDP:192.168.250.103:5060 ---> OPTIONS sip:192.168.250.200 SIP/2.0 From: ;tag=6aec58-67faa8c0-13c4-50029-4f46144a-12f27b6d-4f46144a To: Call-ID: 6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a CSeq: 3 OPTIONS Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46144a-a9bf43da-370b02bb Max-Forwards: 70 Supported: replaces,100rel,eventlist,timer,timer User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) Content-Length: 0 <-------------> [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 0 [ 35]: OPTIONS sip:192.168.250.200 SIP/2.0 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 1 [ 90]: From: ;tag=6aec58-67faa8c0-13c4-50029-4f46144a-12f27b6d-4f46144a [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 2 [ 30]: To: [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 3 [ 61]: Call-ID: 6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 4 [ 15]: CSeq: 3 OPTIONS [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 5 [ 85]: Via: SIP/2.0/UDP 192.168.250.103:5060;rport;branch=z9hG4bK-4f46144a-a9bf43da-370b02bb [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 7 [ 48]: Supported: replaces,100rel,eventlist,timer,timer [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 8 [ 61]: User-Agent: AUDC-IPPhone/1.6.0_build_30 (310HD; 00908F15A845) [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] --- (10 headers 0 lines) --- [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: = Looking for Call ID: 6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a (Checking From) --From tag 6aec58-67faa8c0-13c4-50029-4f46144a-12f27b6d-4f46144a --To-tag [Feb 23 08:26:18] DEBUG[1977] acl.c: For destination '192.168.250.103', our source address is '192.168.250.200'. [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.250.200:5060 [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Allocating new SIP dialog for 6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a - OPTIONS (No RTP) [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 23 08:26:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.200' into... [Feb 23 08:26:18] DEBUG[1977] netsock2.c: ...host '192.168.250.200' and port ''. [Feb 23 08:26:18] DEBUG[1977] netsock2.c: Splitting '192.168.250.103' into... [Feb 23 08:26:18] DEBUG[1977] netsock2.c: ...host '192.168.250.103' and port ''. [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] Looking for s in default (domain 192.168.250.200) [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] <--- Transmitting (NAT) to 192.168.250.103:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.250.103:5060;branch=z9hG4bK-4f46144a-a9bf43da-370b02bb;received=192.168.250.103;rport=5060 From: ;tag=6aec58-67faa8c0-13c4-50029-4f46144a-12f27b6d-4f46144a To: ;tag=as1e51a294 Call-ID: 6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a CSeq: 3 OPTIONS Server: Asterisk PBX 1.8.9.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 23 08:26:18] DEBUG[1977] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.250.103:5060 [Feb 23 08:26:18] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:18] Scheduling destruction of SIP dialog '6aec58-67faa8c0-13c4-50029-4f46144a-e5589f4-4f46144a' in 32000 ms (Method: OPTIONS) [Feb 23 08:26:21] VERBOSE[5268] asterisk.c: [Feb 23 08:26:21] -- Remote UNIX connection disconnected [Feb 23 08:26:30] VERBOSE[1564] asterisk.c: [Feb 23 08:26:30] -- Remote UNIX connection [Feb 23 08:26:40] DEBUG[1977] chan_sip.c: Auto destroying SIP dialog '6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440' [Feb 23 08:26:40] DEBUG[1977] chan_sip.c: Destroying SIP dialog 6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440 [Feb 23 08:26:40] VERBOSE[1977] chan_sip.c: [Feb 23 08:26:40] Really destroying SIP dialog '6addb8-c9faa8c0-13c4-50029-4f461440-4d573961-4f461440' Method: OPTIONS