Proxy-Authenticate: Digest realm="asterisk", nonce="6bca7406" Content-Length: 0 --- Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #110 Scheduling destruction of call '1151492141-148-GRISHIN@81.198.164.119' in 15000 ms Found user '21169' astRiga*CLI> <-- SIP read from 81.198.164.119:5060: ACK sip:22901@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK480148 To: ;tag=as68d6e448 From: "21169" ;tag=8347 Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 579 ACK Max-Forwards: 20 User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: ACK sip:22901@81.198.164.48 SIP/2.0 (35) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK480148 (63) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=as68d6e448 (44) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "21169" ;tag=8347 (48) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151492141-148-GRISHIN@81.198.164.119 (46) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 579 ACK (13) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Content-Length: 0 (17) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1151492141-148-GRISHIN@81.198.164.119' of Response 579: Match Found <-- SIP read from 81.198.164.119:5060: INVITE sip:22901@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK481148 To: From: "21169" ;tag=8347 Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 580 INVITE Max-Forwards: 20 User-Agent: Express Talk 1.04 Contact: Proxy-Authorization: Digest username="21169",realm="asterisk",nonce="6bca7406",uri="sip:22901@81.198.164.48",response="0b0fde87ab3e613022f24fea771df807",opaque="" Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 285 v=0 o=- 816661085 816661090 IN IP4 81.198.164.119 s=Express Talk c=IN IP4 81.198.164.119 t=0 0 m=audio 8000 RTP/AVP 3 0 8 13 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:22901@81.198.164.48 SIP/2.0 (38) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK481148 (63) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "21169" ;tag=8347 (48) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151492141-148-GRISHIN@81.198.164.119 (46) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 580 INVITE (16) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Contact: (40) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Proxy-Authorization: Digest username="21169",realm="asterisk",nonce="6bca7406",uri="sip:22901@81.198.164.48",response="0b0fde87ab3e613022f24fea771df807",opaque="" (162) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY (61) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 11: Supported: replaces (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 12: Content-Type: application/sdp (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 13: Content-Length: 285 (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 14: (0) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: o=- 816661085 816661090 IN IP4 81.198.164.119 (45) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: s=Express Talk (14) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: c=IN IP4 81.198.164.119 (23) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: m=audio 8000 RTP/AVP 3 0 8 13 101 (33) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:13 CN/8000 (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=sendrecv (10) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: (0) --- (14 headers 14 lines)--- Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 1151492141-148-GRISHIN@81.198.164.119 Sending to 81.198.164.119 : 5060 (NAT) Jun 30 00:06:42 DEBUG[26090]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21169' Jun 30 00:06:42 DEBUG[26090]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 524288 Found user '21169' Found RTP audio format 3 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 13 Found RTP audio format 101 Peer audio RTP is at port 81.198.164.119:8000 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 81.198.164.119:8000 Found description format GSM Found description format PCMU Found description format PCMA Found description format CN Found description format telephone-event Capabilities: us - 0x2 (gsm), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x3 (telephone-event|CN), combined - 0x1 (telephone-event) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:10497 handle_request_invite: Checking SIP call limits for device 21169 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call Looking for 22901 in default-sip (domain 81.198.164.48) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: Transmitting (NAT) to 81.198.164.119:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 81.198.164.119:5060;branch=z9hG4bK481148;received=81.198.164.119;rport=5060 From: "21169" ;tag=8347 To: Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 580 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jun 30 00:06:42 DEBUG[26088]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 21169 Jun 30 00:06:42 DEBUG[26088]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21169' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21169-35f4", "CALL_FROM_TYPE=int") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' -- Executing Goto("SIP/21169-35f4", "default|22901|1") in new stack -- Goto (default,22901,1) Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21169-35f4", "__valuee=1111222") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'SetAccount' -- Executing SetAccount("SIP/21169-35f4", "1111222") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "set-var|22901|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21169-35f4", "1?6") in new stack -- Goto (set-var,22901,6) Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "set-var-TO|22901|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21169-35f4", "CALL_TO_TYPE=int") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21169-35f4", "") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21169-35f4", ""CALL_TO_TYPE=int CALL_FROM_TYPE=int"") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21169-35f4", "") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "check-restriction|22901|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21169-35f4", "") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "make-recording|22901|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21169-35f4", "") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' -- Executing Goto("SIP/21169-35f4", "ext-local|22901|1") in new stack -- Goto (ext-local,22901,1) Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21169-35f4", "++++++++++9990000") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "db_deny_out_local|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26088]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21169' at 21169@81.198.164.119:1000 for 120 Jun 30 00:06:42 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for SIP/21169 - state 2 (In use) Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("SIP/21169-35f4", "") Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("SIP/21169-35f4", "1?db_deny_inc_local|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("SIP/21169-35f4", "") Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("SIP/21169-35f4", "0?db_deny_inc_extrn|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21169-35f4", "") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("SIP/21169-35f4", "stdexten|22901|SIP/22901") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21169-35f4", "isext|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21169-35f4", "0?10") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21169-35f4", "Connect connid localhost asterisk frefubresus8p7a& asterisk") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21169-35f4", "Query result1 1 SELECT IF(ext_type='queue','queue','ext') FROM extensions WHERE extension='22901'") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21169-35f4", "Fetch foundRow 2 isExtension") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21169-35f4", "==###CALL_TO_TYPE=int###==var connid = 1====== var result1 = 2 =======var foundRow = 1 ==== var isExtension = queue") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21169-35f4", "Clear 2") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21169-35f4", "Disconnect 1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21169-35f4", "====var connid = 1====ARG1=229===== var result1 = 2 =======var foundRow = 1 ==== var isExtension = queue") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21169-35f4", "0?noext|1") in new stack Jun 30 00:06:42 DEBUG[26270]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:42 DEBUG[26270]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21169-35f4", "1?db_ext_queues|22901|1") in new stack -- Goto (db_ext_queues,22901,1) == Channel 'SIP/21169-35f4' jumping out of macro 'stdexten' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing SetCIDName("SIP/21169-35f4", "22901-----+37128806004") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing SetVar("SIP/21169-35f4", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q-1151615202.10") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing NoOp("SIP/21169-35f4", "FILENAME= /var/spool/asterisk/monitor/q-1151615202.10") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Set("SIP/21169-35f4", "CDR(userfield)=1151615202.10") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' -- Executing Set("SIP/21169-35f4", "agent_count=1") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing NoOp("SIP/21169-35f4", "agent_count(22901) = 1") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' -- Executing GotoIf("SIP/21169-35f4", "0?vm|22600|1") Jun 30 00:06:42 DEBUG[26270]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Set("SIP/21169-35f4", "__qvar_queue=22901") Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22901' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Queue("SIP/21169-35f4", "22901|t|||300") Jun 30 00:06:42 DEBUG[26270]: app_queue.c:3049 queue_exec: NO QUEUE_PRIO variable found. Using default. Jun 30 00:06:42 DEBUG[26270]: app_queue.c:3057 queue_exec: queue: 22901, options: t, url: , announce: , expires: 1151615502, priority: 0 Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_table WHERE name = '22901' Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_member_table WHERE interface LIKE '%' AND queue_name = '22901' ORDER BY interface Jun 30 00:06:42 DEBUG[26270]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26270]: app_queue.c:1156 join_queue: Queue '22901' Join, Channel 'SIP/21169-35f4', Position '1' Jun 30 00:06:42 DEBUG[26270]: channel.c:2167 ast_prod: Prodding channel 'SIP/21169-35f4' We're at 81.198.164.48 port 42636 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Transmitting (NAT) to 81.198.164.119:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 81.198.164.119:5060;branch=z9hG4bK481148;received=81.198.164.119;rport=5060 From: "21169" ;tag=8347 To: ;tag=as1b27fe12 Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 580 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 23813 23813 IN IP4 81.198.164.48 s=session c=IN IP4 81.198.164.48 t=0 0 m=audio 42636 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- -- Started music on hold, class 'ASAP', on SIP/21169-35f4 Jun 30 00:06:42 DEBUG[26270]: app_queue.c:2000 is_our_turn: It's our turn (SIP/21169-35f4). Jun 30 00:06:42 DEBUG[26270]: app_queue.c:2196 try_calling: SIP/21169-35f4 is trying to call a queue member. Jun 30 00:06:42 DEBUG[26270]: app_queue.c:2218 try_calling: Queue with URL=_ Jun 30 00:06:42 DEBUG[26270]: app_queue.c:1621 ring_one: Trying 'Agent/21177' with metric 5001000 Jun 30 00:06:42 DEBUG[26270]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable qvar_queue. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable agent_count. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-10. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-9. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-8. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MYSQL_STATUS. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-7. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-6. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-5. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable foundRow. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable isExtension. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-4. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable result1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-3. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable connid. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-2. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-6. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-5. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-4. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-3. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-2. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-6. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-make-recording-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-5. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-check-restriction-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-4. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-22901-8. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-22901-7. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-TO-22901-2. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable CALL_TO_TYPE. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-TO-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-22901-6. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-3. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-2. Jun 30 00:06:42 DEBUG[26270]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable valuee. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-sip-22901-2. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable CALL_FROM_TYPE. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-sip-22901-1. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPCALLID. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Jun 30 00:06:42 DEBUG[26270]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPURI. -- outgoing agentcall, to agent '21177', on 'Local/21177@default-6a29,1' Jun 30 00:06:42 DEBUG[26270]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable qvar_queue. Jun 30 00:06:42 DEBUG[26270]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable valuee. -- Called Agent/21177 Jun 30 00:06:42 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21177@default - state 2 (In use) Jun 30 00:06:42 DEBUG[26271]: app_queue.c:523 changethread: Device 'SIP/21169' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "__valuee=1111222") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'SetAccount' -- Executing SetAccount("Local/21177@default-6a29,2", "1111222") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "set-var|21177|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?6") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "CALL_FROM_TYPE=ext") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'DBget' -- Executing DBget("Local/21177@default-6a29,2", "USER_IP=SIP/Registry/+37128806004") in new stack -- DBget: varname=USER_IP, family=SIP, key=Registry/+37128806004 Jun 30 00:06:42 DEBUG[26272]: db.c:200 ast_db_get: Unable to find key 'Registry/+37128806004' in family 'SIP' -- DBget: Value not found in database. Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "1?6") in new stack -- Goto (set-var,21177,6) Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "set-var-TO|21177|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "CALL_TO_TYPE=int") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "__B_NUM=21177") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", ""CALL_TO_TYPE=int CALL_FROM_TYPE=ext"") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "check-restriction|21177|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "make-recording|21177|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' -- Executing Goto("Local/21177@default-6a29,2", "ext-local|21177|1") in new stack -- Goto (ext-local,21177,1) Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "++++++++++9990000") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "db_deny_out_local|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("Local/21177@default-6a29,2", "") Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("Local/21177@default-6a29,2", "0?db_deny_inc_local|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("Local/21177@default-6a29,2", "1?db_deny_inc_extrn|+37128806004|1") in new stack Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_extrn' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_extrn' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_extrn' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_extrn' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '+37128806004' AND context = 'db_deny_inc_extrn' AND priority = '1' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_extrn' AND priority = '1' ORDER BY exten Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("Local/21177@default-6a29,2", "") Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("Local/21177@default-6a29,2", "stdexten|21177|SIP/21177") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("Local/21177@default-6a29,2", "isext|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?10") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' Jun 30 00:06:42 DEBUG[26273]: app_queue.c:523 changethread: Device 'Local/21177@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Executing MYSQL("Local/21177@default-6a29,2", "Connect connid localhost asterisk frefubresus8p7a& asterisk") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Query result1 1 SELECT IF(ext_type='queue','queue','ext') FROM extensions WHERE extension='21177'") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Fetch foundRow 2 isExtension") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "==###CALL_TO_TYPE=int###==var connid = 1====== var result1 = 2 =======var foundRow = 1 ==== var isExtension = ext") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Clear 2") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Disconnect 1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "====var connid = 1====ARG1=211===== var result1 = 2 =======var foundRow = 1 ==== var isExtension = ext") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?noext|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?db_ext_queues|21177|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'SetMusicOnHold' -- Executing SetMusicOnHold("Local/21177@default-6a29,2", "default") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'SetCIDName' -- Executing SetCIDName("Local/21177@default-6a29,2", "+37128806004") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?9") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'DBget' -- Executing DBget("Local/21177@default-6a29,2", "USER_IP=SIP/Registry/21177") in new stack -- DBget: varname=USER_IP, family=SIP, key=Registry/21177 -- DBget: set variable USER_IP to 81.198.164.2:2563:3600:21177:sip:21177@192.168.1.216:5070 Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?7:9") in new stack -- Goto (macro-stdexten,s,9) Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "CDR(userfield)=1151615202.12") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'SetAccount' -- Executing SetAccount("Local/21177@default-6a29,2", "33333333") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("Local/21177@default-6a29,2", "0?outdial|1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Connect connid localhost asterisk frefubresus8p7a& asterisk") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Query result1 1 SELECT if(COUNT(*)>0,'forbiden',curdate()) as path FROM extensions WHERE deny_recording=1 AND (extension=+37128806004 OR extension=)") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Fetch foundRow 2 Path") in new stack Jun 30 00:06:42 WARNING[26272]: app_addon_sql_mysql.c:115 find_identifier: Identifier 2, identifier_type 2 not found in identifier list Jun 30 00:06:42 WARNING[26272]: app_addon_sql_mysql.c:330 aMYSQL_fetch: aMYSQL_fetch: Invalid result identifier 2 passed Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("Local/21177@default-6a29,2", "====var connid = 1====== var result1 = 2 =======var Path=") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Clear 2") in new stack Jun 30 00:06:42 WARNING[26272]: app_addon_sql_mysql.c:115 find_identifier: Identifier 2, identifier_type 2 not found in identifier list Jun 30 00:06:42 WARNING[26272]: app_addon_sql_mysql.c:348 aMYSQL_clear: Invalid result identifier 2 passed in aMYSQL_clear Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("Local/21177@default-6a29,2", "Disconnect 1") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("Local/21177@default-6a29,2", "MONITOR_FILENAME=/var/spool/asterisk/monitor//call-1151615202.12") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Monitor' -- Executing Monitor("Local/21177@default-6a29,2", "gsm|/var/spool/asterisk/monitor//call-1151615202.12|mb") in new stack Jun 30 00:06:42 DEBUG[26272]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("Local/21177@default-6a29,2", "SIP/21177|25|dt") in new stack Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' Jun 30 00:06:42 DEBUG[26272]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21177' at 21177@81.198.164.2:2563 for 3600 Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 524288 Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-21. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable AUTO_MONITOR. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-20. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-19. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MYSQL_STATUS. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-18. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-17. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-16. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-15. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-14. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable connid. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-13. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-12. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-11. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-10. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-9. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-6. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable DBGETSTATUS. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable USER_IP. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-5. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-4. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-11. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-10. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-9. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-8. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-7. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-6. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-5. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable foundRow. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable isExtension. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-4. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable result1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-isext-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable ARG2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable ARG1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-6. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-5. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-4. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-ext-local-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-6. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-make-recording-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-5. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-check-restriction-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-4. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-8. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-7. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-TO-21177-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable B_NUM. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-TO-21177-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable CALL_TO_TYPE. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-TO-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-6. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-4. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable CALL_FROM_TYPE. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-set-var-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-3. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-2. Jun 30 00:06:42 DEBUG[26272]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable valuee. Jun 30 00:06:42 DEBUG[26272]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-default-21177-1. Jun 30 00:06:42 DEBUG[26272]: channel.c:2818 ast_channel_inherit_variables: Copying hard-transferable variable qvar_queue. Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:2068 sip_call: Outgoing Call for 21177 Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call We're at 81.198.164.48 port 45046 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:21177@192.168.1.216:5070 SIP/2.0 (43) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport (64) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 2: From: "+37128806004" ;tag=as4a6d2060 (68) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 3: To: (34) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 4: Contact: (41) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 5: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 6: CSeq: 102 INVITE (16) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Asterisk PBX (24) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 8: Max-Forwards: 70 (16) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 9: Date: Thu, 29 Jun 2006 21:06:42 GMT (35) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 217 (19) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: o=root 23813 23813 IN IP4 81.198.164.48 (39) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: s=session (9) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: c=IN IP4 81.198.164.48 (22) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: m=audio 45046 RTP/AVP 3 101 (27) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:3395 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 10 lines Reliably Transmitting (NAT) to 81.198.164.2:2563: INVITE sip:21177@192.168.1.216:5070 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport From: "+37128806004" ;tag=as4a6d2060 To: Contact: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 29 Jun 2006 21:06:42 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 217 v=0 o=root 23813 23813 IN IP4 81.198.164.48 s=session c=IN IP4 81.198.164.48 t=0 0 m=audio 45046 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 30 00:06:42 DEBUG[26272]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #114 -- Called 21177 Jun 30 00:06:42 DEBUG[26272]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to read format gsm Jun 30 00:06:42 DEBUG[26272]: channel.c:2350 set_format: Set channel Local/21177@default-6a29,2 to write format gsm Jun 30 00:06:42 DEBUG[26272]: channel.c:2350 set_format: Set channel Local/21177@default-6a29,2 to read format gsm Jun 30 00:06:42 DEBUG[26272]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to write format gsm astRiga*CLI> <-- SIP read from 81.198.164.2:2563: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport To: ;tag=1121 From: "+37128806004" ;tag=as4a6d2060 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 INVITE User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 180 Ringing (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport (64) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=1121 (43) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "+37128806004" ;tag=as4a6d2060 (68) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: Content-Length: 0 (17) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1445 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #114 - INVITE (got response) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d5d8b0c02688e9031ac076b31475b15@81.198.164.48' Request 102: Found Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite Jun 30 00:06:42 DEBUG[26088]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 21177 Jun 30 00:06:42 DEBUG[26088]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' -- SIP/21177-aa0a is ringing -- Agent/21177 is ringing Jun 30 00:06:42 DEBUG[26088]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21177' at 21177@81.198.164.2:2563 for 3600 Jun 30 00:06:42 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for SIP/21177 - state 6 (Ringing) Jun 30 00:06:42 DEBUG[26274]: app_queue.c:523 changethread: Device 'SIP/21177' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. astRiga*CLI> <-- SIP read from 81.198.164.2:2563: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport To: ;tag=1121 From: "+37128806004" ;tag=as4a6d2060 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 INVITE User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 180 Ringing (19) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport (64) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=1121 (43) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "+37128806004" ;tag=as4a6d2060 (68) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: Content-Length: 0 (17) Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d5d8b0c02688e9031ac076b31475b15@81.198.164.48' Request 102: Found Jun 30 00:06:42 DEBUG[26090]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite -- SIP/21177-aa0a is ringing astRiga*CLI> <-- SIP read from 81.198.164.2:2563: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport To: ;tag=1121 From: "+37128806004" ;tag=as4a6d2060 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 INVITE User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 180 Ringing (19) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport (64) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=1121 (43) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "+37128806004" ;tag=as4a6d2060 (68) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: Content-Length: 0 (17) Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d5d8b0c02688e9031ac076b31475b15@81.198.164.48' Request 102: Found Jun 30 00:06:44 DEBUG[26090]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite -- SIP/21177-aa0a is ringing astRiga*CLI> <-- SIP read from 81.198.164.2:2563: SIP/2.0 200 OK Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport To: ;tag=1121 From: "+37128806004" ;tag=as4a6d2060 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 INVITE User-Agent: Express Talk 1.04 Contact: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY Accept: application/sdp Supported: replaces Content-Type: application/sdp Content-Length: 211 v=0 o=- 816620677 816620683 IN IP4 192.168.1.216 s=Express Talk c=IN IP4 192.168.1.216 t=0 0 m=audio 8000 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: SIP/2.0 200 OK (14) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK234cc42e;rport (64) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=1121 (43) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "+37128806004" ;tag=as4a6d2060 (68) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 102 INVITE (16) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: Contact: (39) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY (55) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Accept: application/sdp (23) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: Supported: replaces (19) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 211 (19) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: o=- 816620677 816620683 IN IP4 192.168.1.216 (44) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: s=Express Talk (14) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: c=IN IP4 192.168.1.216 (22) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: m=audio 8000 RTP/AVP 3 101 (26) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=sendrecv (10) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: (0) --- (13 headers 11 lines)--- Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '7d5d8b0c02688e9031ac076b31475b15@81.198.164.48' of Request 102: Match Found Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:9584 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.216:8000 Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 192.168.1.216:8000 Found description format GSM Found description format telephone-event Capabilities: us - 0x2 (gsm), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.216, port 5070 Transmitting (NAT) to 81.198.164.2:2563: ACK sip:21177@192.168.1.216:5070 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.48:5060;branch=z9hG4bK375d24d7;rport From: "+37128806004" ;tag=as4a6d2060 To: ;tag=1121 Contact: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/21177-aa0a answered Local/21177@default-6a29,2 Jun 30 00:06:45 DEBUG[26272]: channel.c:2350 set_format: Set channel Local/21177@default-6a29,2 to read format gsm Jun 30 00:06:45 DEBUG[26272]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to write format gsm Jun 30 00:06:45 DEBUG[26272]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to read format gsm Jun 30 00:06:45 DEBUG[26272]: channel.c:2350 set_format: Set channel Local/21177@default-6a29,2 to write format gsm Jun 30 00:06:45 DEBUG[26088]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 21177 Jun 30 00:06:45 DEBUG[26088]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' Jun 30 00:06:45 DEBUG[26270]: app_queue.c:1933 wait_for_answer: Dunno what to do with control type -1 -- Agent/21177 answered SIP/21169-35f4 -- Stopped music on hold on SIP/21169-35f4 Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21169-35f4 to write format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21169-35f4 to read format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel Agent/21177 to write format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel Agent/21177 to read format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21169-35f4 to write format gsm Jun 30 00:06:45 DEBUG[26270]: res_monitor.c:201 ast_monitor_start: Cannot start monitoring Agent/21177, already monitored Jun 30 00:06:45 DEBUG[26270]: chan_sip.c:2540 sip_answer: sip_answer(SIP/21169-35f4) We're at 81.198.164.48 port 42636 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 81.198.164.119:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 81.198.164.119:5060;branch=z9hG4bK481148;received=81.198.164.119;rport=5060 From: "21169" ;tag=8347 To: ;tag=as1b27fe12 Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 580 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 23813 23814 IN IP4 81.198.164.48 s=session c=IN IP4 81.198.164.48 t=0 0 m=audio 42636 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 30 00:06:45 DEBUG[26270]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #116 astRiga*CLI> <-- SIP read from 81.198.164.119:5060: ACK sip:22901@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK482148 To: ;tag=as1b27fe12 From: "21169" ;tag=8347 Call-ID: 1151492141-148-GRISHIN@81.198.164.119 CSeq: 580 ACK Max-Forwards: 20 User-Agent: Express Talk 1.04 Proxy-Authorization: Digest username="21169",realm="asterisk",nonce="6bca7406",uri="sip:22901@81.198.164.48",response="0b0fde87ab3e613022f24fea771df807",opaque="" Content-Length: 0 Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: ACK sip:22901@81.198.164.48 SIP/2.0 (35) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.119:5060;rport;branch=z9hG4bK482148 (63) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=as1b27fe12 (44) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "21169" ;tag=8347 (48) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151492141-148-GRISHIN@81.198.164.119 (46) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 580 ACK (13) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Proxy-Authorization: Digest username="21169",realm="asterisk",nonce="6bca7406",uri="sip:22901@81.198.164.48",response="0b0fde87ab3e613022f24fea771df807",opaque="" (162) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Content-Length: 0 (17) Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #116 Jun 30 00:06:45 DEBUG[26090]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1151492141-148-GRISHIN@81.198.164.119' of Response 580: Match Found Jun 30 00:06:45 DEBUG[26088]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21177' at 21177@81.198.164.2:2563 for 3600 Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for SIP/21177 - state 2 (In use) Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21177@default - state 2 (In use) Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21177@default - state 2 (In use) Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Agent/21177 - state 3 (Busy) Jun 30 00:06:45 DEBUG[26088]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 21169 Jun 30 00:06:45 DEBUG[26088]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21169' Jun 30 00:06:45 DEBUG[26276]: app_queue.c:523 changethread: Device 'SIP/21177' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26088]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21169' at 21169@81.198.164.119:1000 for 120 Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for SIP/21169 - state 2 (In use) Jun 30 00:06:45 DEBUG[26277]: app_queue.c:523 changethread: Device 'Local/21177@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26278]: app_queue.c:523 changethread: Device 'Local/21177@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26279]: app_queue.c:492 changethread: Device 'Agent/21177' changed to state '3' (Busy) Jun 30 00:06:45 DEBUG[26280]: app_queue.c:523 changethread: Device 'SIP/21169' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26272]: rtp.c:479 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 81.198.164.2:8000 Jun 30 00:06:45 DEBUG[26272]: channel.c:2757 ast_channel_masquerade: Planning to masquerade channel SIP/21177-aa0a into the structure of Local/21177@default-6a29,1 Jun 30 00:06:45 DEBUG[26272]: channel.c:2770 ast_channel_masquerade: Done planning to masquerade channel SIP/21177-aa0a into the structure of Local/21177@default-6a29,1 Jun 30 00:06:45 DEBUG[26272]: chan_local.c:244 local_write: Not posting to queue since already masked on 'Local/21177@default-6a29,2' Jun 30 00:06:45 DEBUG[26270]: channel.c:2880 ast_do_masquerade: Actually Masquerading SIP/21177-aa0a(6) into the structure of Local/21177@default-6a29,1(6) Jun 30 00:06:45 DEBUG[26270]: channel.c:2891 ast_do_masquerade: Got clone lock for masquerade on 'SIP/21177-aa0a' at 0x8371e0 Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to write format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21177-aa0a to read format gsm Jun 30 00:06:45 DEBUG[26270]: channel.c:3052 ast_do_masquerade: Putting channel SIP/21177-aa0a in 2/2 formats Jun 30 00:06:45 DEBUG[26270]: channel.c:3087 ast_do_masquerade: Released clone lock on 'Local/21177@default-6a29,1' Jun 30 00:06:45 DEBUG[26270]: channel.c:3096 ast_do_masquerade: Done Masquerading SIP/21177-aa0a (6) Jun 30 00:06:45 DEBUG[26270]: chan_agent.c:547 agent_read: Bridge on 'SIP/21177-aa0a' being set to 'Agent/21177' (3) Jun 30 00:06:45 DEBUG[26272]: channel.c:3275 ast_generic_bridge: Didn't get a frame from channel: Local/21177@default-6a29,2 Jun 30 00:06:45 DEBUG[26272]: channel.c:3550 ast_channel_bridge: Bridge stops bridging channels Local/21177@default-6a29,2 and Local/21177@default-6a29,1 Jun 30 00:06:45 DEBUG[26272]: channel.c:1328 ast_hangup: Hanging up zombie 'Local/21177@default-6a29,1' Jun 30 00:06:45 DEBUG[26272]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jun 30 00:06:45 DEBUG[26272]: app_macro.c:231 macro_exec: Spawn extension (macro-stdexten,s,21) exited non-zero on 'Local/21177@default-6a29,2' in macro 'stdexten' Jun 30 00:06:45 DEBUG[26272]: pbx.c:2316 __ast_pbx_run: Spawn extension (macro-stdexten,s,21) exited non-zero on 'Local/21177@default-6a29,2' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"+37128806004" <+37128806004>' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '+37128806004' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '21177' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ext-local' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/21177@default-6a29,2' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/21177-aa0a' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Monitor' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'gsm|/var/spool/asterisk/monitor//call-1151615202.12|mX' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-30 00:06:42' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-30 00:06:45' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-06-30 00:06:45' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '3' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '33333333' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1151615202.12' Jun 30 00:06:45 DEBUG[26272]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1151615202.12' Jun 30 00:06:45 DEBUG[26088]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'Local/21177@default-6a29,2' Jun 30 00:06:45 DEBUG[26272]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Jun 30 00:06:45 DEBUG[26272]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2006-06-30 00:06:42','\"+37128806004\" <+37128806004>','+37128806004','21177','ext-local', 'Local/21177@default-6a29,2','SIP/21177-aa0a','Monitor','gsm|/var/spool/asterisk/monitor//call-1151615202.12|mX',3,0,'ANSWERED',3,'33333333','1151615202.12') Jun 30 00:06:45 DEBUG[26272]: channel.c:1323 ast_hangup: Hanging up channel 'Local/21177@default-6a29,2' Jun 30 00:06:45 DEBUG[26272]: res_monitor.c:281 ast_monitor_stop: monitor executing ( nice -n 19 soxmix "//var/spool/asterisk/monitor//call-1151615202.12-in.gsm" "//var/spool/asterisk/monitor//call-1151615202.12-out.gsm" "//var/spool/asterisk/monitor//call-1151615202.12.gsm" && rm -f "//var/spool/asterisk/monitor//call-1151615202.12-"* ) & Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21177@default - state 0 (Unknown) Jun 30 00:06:45 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21177@default - state 0 (Unknown) Jun 30 00:06:45 DEBUG[26284]: app_queue.c:523 changethread: Device 'Local/21177@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26285]: app_queue.c:523 changethread: Device 'Local/21177@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Jun 30 00:06:45 DEBUG[26270]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to gsm Jun 30 00:06:45 DEBUG[26270]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to gsm astRiga*CLI> <-- SIP read from 81.198.164.119:1000: OPTIONS sip:81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 81.198.164.119:1000;rport;branch=z9hG4bK51c6a4770000000b44a3e5fd00001fee00008ae4 Content-Length: 0 Call-ID: 023E9340-680D-4B7C-8964-355036A28106@81.198.164.119 CSeq: 4313 OPTIONS From: ;tag=56900801523018 Max-Forwards: 70 To: Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: OPTIONS sip:81.198.164.48 SIP/2.0 (33) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 81.198.164.119:1000;rport;branch=z9hG4bK51c6a4770000000b44a3e5fd00001fee00008ae4 (97) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: Content-Length: 0 (17) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: Call-ID: 023E9340-680D-4B7C-8964-355036A28106@81.198.164.119 (60) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: CSeq: 4313 OPTIONS (18) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: From: ;tag=56900801523018 (50) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 70 (16) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: To: (23) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: (0) --- (8 headers 0 lines)--- Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 023E9340-680D-4B7C-8964-355036A28106@81.198.164.119 - OPTIONS (No RTP) Jun 30 00:06:47 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default-sip (domain 81.198.164.48) Transmitting (no NAT) to 81.198.164.119:1000: SIP/2.0 200 OK Via: SIP/2.0/UDP 81.198.164.119:1000;rport;branch=z9hG4bK51c6a4770000000b44a3e5fd00001fee00008ae4;received=81.198.164.119 From: ;tag=56900801523018 To: ;tag=as0e034ba5 Call-ID: 023E9340-680D-4B7C-8964-355036A28106@81.198.164.119 CSeq: 4313 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 --- Destroying call '023E9340-680D-4B7C-8964-355036A28106@81.198.164.119' astRiga*CLI> <-- SIP read from 81.198.164.2:2563: INVITE sip:+37128806004@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK953600 To: "+37128806004" ;tag=as4a6d2060 From: ;tag=1121 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 1 INVITE Max-Forwards: 20 User-Agent: Express Talk 1.04 Contact: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 283 v=0 o=- 816620677 816620685 IN IP4 192.168.1.216 s=Express Talk c=IN IP4 192.168.1.216 t=0 0 m=audio 8000 RTP/AVP 3 0 8 13 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendonly Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:+37128806004@81.198.164.48 SIP/2.0 (45) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK953600 (62) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: "+37128806004" ;tag=as4a6d2060 (66) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: ;tag=1121 (45) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 1 INVITE (14) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Contact: (39) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY (61) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: Supported: replaces (19) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 283 (19) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: o=- 816620677 816620685 IN IP4 192.168.1.216 (44) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: s=Express Talk (14) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: c=IN IP4 192.168.1.216 (22) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: m=audio 8000 RTP/AVP 3 0 8 13 101 (33) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:13 CN/8000 (19) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=sendonly (10) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: (0) --- (13 headers 14 lines)--- Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1004 parse_sip_options: Begin: parsing SIP "Supported: replaces" Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1016 parse_sip_options: Found SIP option: -replaces- Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1022 parse_sip_options: Matched SIP option: replaces Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1033 parse_sip_options: * SIP extension value: 1 for call 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 Using INVITE request as basis request - 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 Sending to 192.168.1.216 : 5070 (NAT) Found RTP audio format 3 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 13 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.216:8000 Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 192.168.1.216:8000 Found description format GSM Found description format PCMU Found description format PCMA Found description format CN Found description format telephone-event Capabilities: us - 0x2 (gsm), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x3 (telephone-event|CN), combined - 0x1 (telephone-event) Jun 30 00:06:48 DEBUG[26090]: chan_agent.c:927 agent_bridgedchannel: Asked for bridged channel on 'SIP/21177-aa0a'/'Agent/21177', returning 'SIP/21169-35f4' -- Started music on hold, class 'default', on SIP/21169-35f4 Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:10551 handle_request_invite: Got a SIP re-invite for call 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 We're at 81.198.164.48 port 45046 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 81.198.164.2:2563: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.216:5070;branch=z9hG4bK953600;received=81.198.164.2;rport=2563 From: ;tag=1121 To: "+37128806004" ;tag=as4a6d2060 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 23813 23814 IN IP4 81.198.164.48 s=session c=IN IP4 81.198.164.48 t=0 0 m=audio 45046 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #119 astRiga*CLI> <-- SIP read from 81.198.164.2:2563: ACK sip:+37128806004@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK963600 To: "+37128806004" ;tag=as4a6d2060 From: ;tag=1121 Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 CSeq: 1 ACK Max-Forwards: 20 User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: ACK sip:+37128806004@81.198.164.48 SIP/2.0 (42) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK963600 (62) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: "+37128806004" ;tag=as4a6d2060 (66) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: ;tag=1121 (45) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 7d5d8b0c02688e9031ac076b31475b15@81.198.164.48 (55) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 1 ACK (11) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Content-Length: 0 (17) Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #119 Jun 30 00:06:48 DEBUG[26090]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '7d5d8b0c02688e9031ac076b31475b15@81.198.164.48' of Response 1: Match Found Jun 30 00:06:48 DEBUG[26270]: channel.c:2350 set_format: Set channel SIP/21169-35f4 to write format slin Jun 30 00:06:48 DEBUG[26270]: res_musiconhold.c:233 ast_moh_files_next: SIP/21169-35f4 Opened file 0 '/var/lib/asterisk/mohmp3/01 - Who Made Who' astRiga*CLI> <-- SIP read from 81.198.164.2:2563: INVITE sip:22902@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK973600 To: From: "Name" ;tag=1122 Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 641 INVITE Max-Forwards: 20 User-Agent: Express Talk 1.04 Contact: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 283 v=0 o=- 816620678 816620683 IN IP4 192.168.1.216 s=Express Talk c=IN IP4 192.168.1.216 t=0 0 m=audio 8002 RTP/AVP 3 0 8 13 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:22902@81.198.164.48 SIP/2.0 (38) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK973600 (62) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "Name" ;tag=1122 (47) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151576126-3600-SHULGA@192.168.1.216 (45) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 641 INVITE (16) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Contact: (39) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY (61) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: Supported: replaces (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 11: Content-Type: application/sdp (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 12: Content-Length: 283 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 13: (0) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: o=- 816620678 816620683 IN IP4 192.168.1.216 (44) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: s=Express Talk (14) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: c=IN IP4 192.168.1.216 (22) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: m=audio 8002 RTP/AVP 3 0 8 13 101 (33) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:13 CN/8000 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=sendrecv (10) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: (0) --- (13 headers 14 lines)--- Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 1151576126-3600-SHULGA@192.168.1.216 - INVITE (With RTP) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1004 parse_sip_options: Begin: parsing SIP "Supported: replaces" Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1016 parse_sip_options: Found SIP option: -replaces- Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1022 parse_sip_options: Matched SIP option: replaces Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1033 parse_sip_options: * SIP extension value: 1 for call 1151576126-3600-SHULGA@192.168.1.216 Using INVITE request as basis request - 1151576126-3600-SHULGA@192.168.1.216 Sending to 192.168.1.216 : 5070 (NAT) Jun 30 00:06:54 DEBUG[26090]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' Jun 30 00:06:54 DEBUG[26090]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 524288 Reliably Transmitting (NAT) to 81.198.164.2:2563: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.216:5070;branch=z9hG4bK973600;received=81.198.164.2;rport=2563 From: "Name" ;tag=1122 To: ;tag=as36dcae57 Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 641 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest realm="asterisk", nonce="79c41e25" Content-Length: 0 --- Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #120 Scheduling destruction of call '1151576126-3600-SHULGA@192.168.1.216' in 15000 ms Found user '21177' astRiga*CLI> <-- SIP read from 81.198.164.2:2563: ACK sip:22902@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK973600 To: ;tag=as36dcae57 From: "Name" ;tag=1122 Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 641 ACK Max-Forwards: 20 User-Agent: Express Talk 1.04 Content-Length: 0 Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: ACK sip:22902@81.198.164.48 SIP/2.0 (35) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK973600 (62) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: ;tag=as36dcae57 (44) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "Name" ;tag=1122 (47) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151576126-3600-SHULGA@192.168.1.216 (45) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 641 ACK (13) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Content-Length: 0 (17) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: (0) --- (9 headers 0 lines)--- Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #120 Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1151576126-3600-SHULGA@192.168.1.216' of Response 641: Match Found <-- SIP read from 81.198.164.2:2563: INVITE sip:22902@81.198.164.48 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK983600 To: From: "Name" ;tag=1122 Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 642 INVITE Max-Forwards: 20 User-Agent: Express Talk 1.04 Contact: Proxy-Authorization: Digest username="21177",realm="asterisk",nonce="79c41e25",uri="sip:22902@81.198.164.48",response="53d256387b367ddc0a3ad2da949c235c",opaque="" Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 283 v=0 o=- 816620678 816620683 IN IP4 192.168.1.216 s=Express Talk c=IN IP4 192.168.1.216 t=0 0 m=audio 8002 RTP/AVP 3 0 8 13 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 0: INVITE sip:22902@81.198.164.48 SIP/2.0 (38) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.216:5070;rport;branch=z9hG4bK983600 (62) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 2: To: (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 3: From: "Name" ;tag=1122 (47) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 4: Call-ID: 1151576126-3600-SHULGA@192.168.1.216 (45) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 5: CSeq: 642 INVITE (16) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 6: Max-Forwards: 20 (16) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 7: User-Agent: Express Talk 1.04 (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 8: Contact: (39) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 9: Proxy-Authorization: Digest username="21177",realm="asterisk",nonce="79c41e25",uri="sip:22902@81.198.164.48",response="53d256387b367ddc0a3ad2da949c235c",opaque="" (162) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, INFO, REFER, NOTIFY (61) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 11: Supported: replaces (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 12: Content-Type: application/sdp (29) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 13: Content-Length: 283 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3363 parse_request: Header 14: (0) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: v=0 (3) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: o=- 816620678 816620683 IN IP4 192.168.1.216 (44) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: s=Express Talk (14) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: c=IN IP4 192.168.1.216 (22) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: t=0 0 (5) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: m=audio 8002 RTP/AVP 3 0 8 13 101 (33) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:13 CN/8000 (19) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=fmtp:101 0-16 (15) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: a=sendrecv (10) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3395 parse_request: Line: (0) --- (14 headers 14 lines)--- Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:11137 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 1151576126-3600-SHULGA@192.168.1.216 Sending to 192.168.1.216 : 5070 (NAT) Jun 30 00:06:54 DEBUG[26090]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' Jun 30 00:06:54 DEBUG[26090]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 524288 Found user '21177' Found RTP audio format 3 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 13 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.216:8002 Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:3604 process_sdp: Peer audio RTP is at port 192.168.1.216:8002 Found description format GSM Found description format PCMU Found description format PCMA Found description format CN Found description format telephone-event Capabilities: us - 0x2 (gsm), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x3 (telephone-event|CN), combined - 0x1 (telephone-event) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:10497 handle_request_invite: Checking SIP call limits for device 21177 Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call Looking for 22902 in default-sip (domain 81.198.164.48) Jun 30 00:06:54 DEBUG[26090]: chan_sip.c:6137 build_route: build_route: Contact hop: list_route: hop: Transmitting (NAT) to 81.198.164.2:2563: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.216:5070;branch=z9hG4bK983600;received=81.198.164.2;rport=2563 From: "Name" ;tag=1122 To: Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 642 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jun 30 00:06:54 DEBUG[26088]: chan_sip.c:11668 sip_devicestate: Checking device state for peer 21177 Jun 30 00:06:54 DEBUG[26088]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_buddies WHERE name = '21177' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21177-f731", "CALL_FROM_TYPE=int") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' -- Executing Goto("SIP/21177-f731", "default|22902|1") in new stack -- Goto (default,22902,1) Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21177-f731", "__valuee=1111222") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'SetAccount' -- Executing SetAccount("SIP/21177-f731", "1111222") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "set-var|22902|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21177-f731", "1?6") in new stack -- Goto (set-var,22902,6) Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "set-var-TO|22902|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/21177-f731", "CALL_TO_TYPE=int") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21177-f731", "") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21177-f731", ""CALL_TO_TYPE=int CALL_FROM_TYPE=int"") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21177-f731", "") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "check-restriction|22902|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21177-f731", "") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "make-recording|22902|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Return' -- Executing Return("SIP/21177-f731", "") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' -- Executing Goto("SIP/21177-f731", "ext-local|22902|1") in new stack -- Goto (ext-local,22902,1) Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21177-f731", "++++++++++9990000") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "db_deny_out_local|21177|1") in new stack Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26088]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- SIP Seeding peer from astdb: '21177' at 21177@81.198.164.2:2563 for 3600 Jun 30 00:06:54 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for SIP/21177 - state 2 (In use) Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_out_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_out_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("SIP/21177-f731", "") Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("SIP/21177-f731", "1?db_deny_inc_local|21177|1") in new stack Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '21177' AND context = 'db_deny_inc_local' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\_%' AND context = 'db_deny_inc_local' AND priority = '1' ORDER BY exten Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Return("SIP/21177-f731", "") Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GosubIf' -- Executing GosubIf("SIP/21177-f731", "0?db_deny_inc_extrn|21177|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21177-f731", "") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("SIP/21177-f731", "stdexten|22902|SIP/22902") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'Gosub' -- Executing Gosub("SIP/21177-f731", "isext|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21177-f731", "0?10") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21177-f731", "Connect connid localhost asterisk frefubresus8p7a& asterisk") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21177-f731", "Query result1 1 SELECT IF(ext_type='queue','queue','ext') FROM extensions WHERE extension='22902'") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21177-f731", "Fetch foundRow 2 isExtension") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21177-f731", "==###CALL_TO_TYPE=int###==var connid = 1====== var result1 = 2 =======var foundRow = 1 ==== var isExtension = queue") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21177-f731", "Clear 2") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'MYSQL' -- Executing MYSQL("SIP/21177-f731", "Disconnect 1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/21177-f731", "====var connid = 1====ARG1=229===== var result1 = 2 =======var foundRow = 1 ==== var isExtension = queue") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21177-f731", "0?noext|1") in new stack Jun 30 00:06:54 DEBUG[26286]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jun 30 00:06:54 DEBUG[26286]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/21177-f731", "1?db_ext_queues|22902|1") in new stack -- Goto (db_ext_queues,22902,1) == Channel 'SIP/21177-f731' jumping out of macro 'stdexten' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '1' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing SetCIDName("SIP/21177-f731", "22902-----21177") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '2' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing SetVar("SIP/21177-f731", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q-1151615214.15") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '3' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing NoOp("SIP/21177-f731", "FILENAME= /var/spool/asterisk/monitor/q-1151615214.15") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '4' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Set("SIP/21177-f731", "CDR(userfield)=1151615214.15") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '5' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' -- Executing Set("SIP/21177-f731", "agent_count=1") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '6' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing NoOp("SIP/21177-f731", "agent_count(22902) = 1") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '7' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' -- Executing GotoIf("SIP/21177-f731", "0?vm|22400|1") Jun 30 00:06:54 DEBUG[26286]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '8' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Set("SIP/21177-f731", "__qvar_queue=22902") Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '22902' AND context = 'db_ext_queues' AND priority = '9' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. -- Executing Queue("SIP/21177-f731", "22902|t|||300") Jun 30 00:06:54 DEBUG[26286]: app_queue.c:3049 queue_exec: NO QUEUE_PRIO variable found. Using default. Jun 30 00:06:54 DEBUG[26286]: app_queue.c:3057 queue_exec: queue: 22902, options: t, url: , announce: , expires: 1151615514, priority: 0 Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:125 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_table WHERE name = '22902' Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:237 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_member_table WHERE interface LIKE '%' AND queue_name = '22902' ORDER BY interface Jun 30 00:06:54 DEBUG[26286]: res_config_mysql.c:636 mysql_reconnect: MySQL RealTime: Everything is fine. Jun 30 00:06:54 DEBUG[26286]: app_queue.c:1156 join_queue: Queue '22902' Join, Channel 'SIP/21177-f731', Position '1' Jun 30 00:06:54 DEBUG[26286]: channel.c:2167 ast_prod: Prodding channel 'SIP/21177-f731' We're at 81.198.164.48 port 49988 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP Transmitting (NAT) to 81.198.164.2:2563: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.216:5070;branch=z9hG4bK983600;received=81.198.164.2;rport=2563 From: "Name" ;tag=1122 To: ;tag=as5f43c6d8 Call-ID: 1151576126-3600-SHULGA@192.168.1.216 CSeq: 642 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=root 23813 23813 IN IP4 81.198.164.48 s=session c=IN IP4 81.198.164.48 t=0 0 m=audio 49988 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- -- Started music on hold, class 'ASAP', on SIP/21177-f731 Jun 30 00:06:54 DEBUG[26286]: app_queue.c:2000 is_our_turn: It's our turn (SIP/21177-f731). Jun 30 00:06:54 DEBUG[26286]: app_queue.c:2196 try_calling: SIP/21177-f731 is trying to call a queue member. Jun 30 00:06:54 DEBUG[26286]: app_queue.c:2218 try_calling: Queue with URL=_ Jun 30 00:06:54 DEBUG[26286]: app_queue.c:1621 ring_one: Trying 'Agent/21169' with metric 5001000 Jun 30 00:06:54 DEBUG[26088]: devicestate.c:187 do_state_change: Changing state for Local/21169@default - state 2 (In use) Jun 30 00:06:54 DEBUG[26287]: app_queue.c:523 changethread: Device 'SIP/21177' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:06:54 DEBUG[26288]: app_queue.c:523 changethread: Device 'Local/21169@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jun 30 00:07:03 DEBUG[26290]: manager.c:1249 process_message: Manager received command 'login' Jun 30 00:07:03 DEBUG[26290]: config.c:595 config_text_file_load: Parsing /etc/asterisk/manager.conf Jun 30 00:07:03 DEBUG[26290]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Jun 30 00:07:03 DEBUG[26290]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Jun 30 00:07:03 DEBUG[26290]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 Jun 30 00:07:03 DEBUG[26290]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 == Manager 'admin' logged on from 127.0.0.1 Jun 30 00:07:03 DEBUG[26290]: manager.c:1249 process_message: Manager received command 'Command' Jun 30 00:07:03 DEBUG[26290]: chan_agent.c:927 agent_bridgedchannel: Asked for bridged channel on 'SIP/21177-aa0a'/'Agent/21177', returning 'SIP/21169-35f4' Jun 30 00:07:03 DEBUG[26290]: chan_agent.c:927 agent_bridgedchannel: Asked for bridged channel on 'SIP/21169-35f4'/'Agent/21177', returning 'SIP/21177-aa0a' Jun 30 00:07:03 DEBUG[26290]: manager.c:1249 process_message: Manager received command 'Logoff' == Manager 'admin' logged off from 127.0.0.1 Jun 30 00:07:03 DEBUG[26291]: manager.c:1249 process_message: Manager received command 'login' Jun 30 00:07:03 DEBUG[26291]: config.c:595 config_text_file_load: Parsing /etc/asterisk/manager.conf Jun 30 00:07:03 DEBUG[26291]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Jun 30 00:07:03 DEBUG[26291]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Jun 30 00:07:03 DEBUG[26291]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 Jun 30 00:07:03 DEBUG[26291]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 == Manager 'admin' logged on from 127.0.0.1 Jun 30 00:07:03 DEBUG[26291]: manager.c:1249 process_message: Manager received command 'Command' astRiga*CLI> show queues astRiga*CLI> show queues astRiga*CLI> show queues astRiga*CLI> se [root@astRiga asterisk]#