Debug Report 2006-09-23 ----------------------------------- mySQL database ----------------------------------- NOT WORKING IF ulaw is in codec list field disallow is all field allow is gsm;ulaw;alaw;g726 ----------------------------------- No problems if using NOT ulaw in codec list, provider supports also g726 and gsm field allow is gsm;alaw;g726 - OK field allow is g726,gsm;alaw - OK ----------------------------------- ---------------------------------------------------------------------- ---------------------------------------------------------------------- ---------------------------------------------------------------------- This debug report is for field allow is gsm;ulaw;alaw;g726 ---------------------------------------------------------------------- -- Executing NoOp("SIP/210-081c90e0", "Test: Codec Test") in new stack Sep 23 11:34:51 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/210-081c90e0", "SIP/004989758585@out_provider") in new stack Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3166 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Sep 23 11:34:51 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:51 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = '210' Sep 23 11:34:51 DEBUG[4647]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Sep 23 11:34:51 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:51 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for SIP/210 - state 2 (In use) Sep 23 11:34:51 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer 210 Sep 23 11:34:51 DEBUG[4824]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:51 DEBUG[4824]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'out_provider' Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:1883 create_addr_from_peer: Setting NAT on RTP to 524288 Sep 23 11:34:51 DEBUG[4824]: acl.c:211 ast_apply_ha: ##### Testing 194.120.0.203 with 192.168.2.0 Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:1127 ast_sip_ouraddrfor: Target address 194.120.0.203 is not local, substituting externip Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3166 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Sep 23 11:34:51 DEBUG[4665]: acl.c:211 ast_apply_ha: ##### Testing 192.168.2.210 with 192.168.2.0 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: NOTIFY sip:210@192.168.2.210 SIP/2.0 (36) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.100:5060;branch=z9hG4bK2d569b50;rport (64) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "asterisk" ;tag=as70309ed1 (60) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: (27) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: (37) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 7a25015d01d4d3031e9c10942311ab18@192.168.2.100 (55) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 102 NOTIFY (16) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: Asterisk PBX (24) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Max-Forwards: 70 (16) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Event: message-summary (22) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Type: application/simple-message-summary (48) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: Content-Length: 94 (18) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 12: (0) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: Messages-Waiting: no (20) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: Message-Account: sip:asterisk@192.168.2.100 (43) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: Voice-Message: 0/57 (0/0) (25) 12 headers, 3 lines Reliably Transmitting (no NAT) to 192.168.2.210:5060: NOTIFY sip:210@192.168.2.210 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.100:5060;branch=z9hG4bK2d569b50;rport From: "asterisk" ;tag=as70309ed1 To: Contact: Call-ID: 7a25015d01d4d3031e9c10942311ab18@192.168.2.100 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:asterisk@192.168.2.100 Voice-Message: 0/57 (0/0) --- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #40 Scheduling destruction of call '7a25015d01d4d3031e9c10942311ab18@192.168.2.100' in 15000 ms Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal_context-872-2. Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal_context-872-1. Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID. Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Sep 23 11:34:51 DEBUG[4824]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI. Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:2077 sip_call: Outgoing Call for 004989758585 Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:2215 update_call_counter: Updating call counter for outgoing call We're at 84.187.5.229 port 10266 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x10 (g726) to SDP Adding non-codec 0x1 (telephone-event) to SDP Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 0: INVITE sip:004989758585@sip.voipcheap.com SIP/2.0 (51) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK604b4e44;rport (63) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 3: To: (42) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 4: Contact: (31) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 6: CSeq: 102 INVITE (16) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 7: User-Agent: Asterisk PBX (24) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 8: Max-Forwards: 70 (16) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 9: Date: Sat, 23 Sep 2006 09:34:51 GMT (35) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 11: Content-Type: application/sdp (29) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 12: Content-Length: 292 (19) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3382 parse_request: Header 13: (0) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: v=0 (3) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: o=root 4642 4642 IN IP4 84.187.5.229 (36) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: s=session (9) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: c=IN IP4 84.187.5.229 (21) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: t=0 0 (5) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: m=audio 10266 RTP/AVP 0 3 8 111 101 (35) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=fmtp:101 0-16 (15) Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:3414 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 13 lines Reliably Transmitting (NAT) to 194.120.0.203:5060: INVITE sip:004989758585@sip.voipcheap.com SIP/2.0 Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK604b4e44;rport From: "Grandstream Bt101" ;tag=as333d6792 To: Contact: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Sat, 23 Sep 2006 09:34:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 292 v=0 o=root 4642 4642 IN IP4 84.187.5.229 s=session c=IN IP4 84.187.5.229 t=0 0 m=audio 10266 RTP/AVP 0 3 8 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 23 11:34:51 DEBUG[4824]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #42 -- Called 004989758585@out_provider Sep 23 11:34:51 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to read format slin Sep 23 11:34:51 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/210-081c90e0 to write format slin Sep 23 11:34:51 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/210-081c90e0 to read format slin Sep 23 11:34:51 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to write format slin Sep 23 11:34:51 DEBUG[4825]: app_queue.c:490 changethread: Device 'SIP/210' changed to state '2' (In use) but we don't care because they're not a member of any queue. <-- SIP read from 192.168.2.210:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.100:5060;branch=z9hG4bK2d569b50;rport From: "asterisk" ;tag=as70309ed1 To: ;tag=df31eb14c48b4a5e Call-ID: 7a25015d01d4d3031e9c10942311ab18@192.168.2.100 CSeq: 102 NOTIFY User-Agent: Grandstream BT100 1.0.6.7 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 200 OK (14) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.100:5060;branch=z9hG4bK2d569b50;rport (64) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "asterisk" ;tag=as70309ed1 (60) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=df31eb14c48b4a5e (48) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Call-ID: 7a25015d01d4d3031e9c10942311ab18@192.168.2.100 (55) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: CSeq: 102 NOTIFY (16) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: User-Agent: Grandstream BT100 1.0.6.7 (37) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: Contact: (32) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Supported: replaces (19) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Length: 0 (17) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #40 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '7a25015d01d4d3031e9c10942311ab18@192.168.2.100' of Request 102: Match Found Destroying call '7a25015d01d4d3031e9c10942311ab18@192.168.2.100' <-- SIP read from 194.120.0.203:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK604b4e44;rport From: "Grandstream Bt101" ;tag=as333d6792 To: Contact: sip:004989758585@194.120.0.203:5060 Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 102 INVITE User-Agent: (Very nice Sip Registrar Server) Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS WWW-Authenticate: Digest realm="sipdiscount.com" ,nonce="2904060112" ,algorithm=MD5 Content-Length: 0 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 401 Unauthorized (24) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK604b4e44;rport (63) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: (42) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: sip:004989758585@194.120.0.203:5060 (46) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 102 INVITE (16) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: (Very nice Sip Registrar Server) (44) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS (45) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: WWW-Authenticate: Digest realm="sipdiscount.com" ,nonce="2904060112" ,algorithm=MD5 (83) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Length: 0 (17) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1388 __sip_ack: Acked pending invite 102 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' of Request 102: Match Found Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:9601 handle_response_invite: SIP response 401 to standard invite Transmitting (NAT) to 194.120.0.203:5060: ACK sip:004989758585@sip.voipcheap.com SIP/2.0 Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK604b4e44;rport From: "Grandstream Bt101" ;tag=as333d6792 To: Contact: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:9040 do_proxy_auth: Auth attempt 1 on INVITE We're at 84.187.5.229 port 10266 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x10 (g726) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 194.120.0.203:5060: INVITE sip:004989758585@sip.voipcheap.com SIP/2.0 Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport From: "Grandstream Bt101" ;tag=as333d6792 To: Contact: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Authorization: Digest username="username", realm="sipdiscount.com", algorithm=MD5, uri="sip:004989758585@sip.voipcheap.com", nonce="2904060112", response="49b9d64852b05e5e47bee5eb0ba811bf", opaque="" Date: Sat, 23 Sep 2006 09:34:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 292 v=0 o=root 4642 4643 IN IP4 84.187.5.229 s=session c=IN IP4 84.187.5.229 t=0 0 m=audio 10266 RTP/AVP 0 3 8 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #43 <-- SIP read from 194.120.0.203:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport From: "Grandstream Bt101" ;tag=as333d6792 To: Contact: sip:004989758585@194.120.0.203:5060 Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 103 INVITE User-Agent: (Very nice Sip Registrar Server) Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS Content-Length: 0 Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 100 Trying (18) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport (63) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: (42) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: sip:004989758585@194.120.0.203:5060 (46) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 103 INVITE (16) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: (Very nice Sip Registrar Server) (44) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS (45) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Content-Length: 0 (17) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1454 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #43 - INVITE (got response) Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:1463 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' Request 103: Found Sep 23 11:34:51 DEBUG[4665]: chan_sip.c:9601 handle_response_invite: SIP response 100 to standard invite <-- SIP read from 194.120.0.203:5060: SIP/2.0 183 Session progress Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport From: "Grandstream Bt101" ;tag=as333d6792 To: ;tag=cb0078c24509605282a20 Contact: sip:004989758585@194.120.0.203:5060 Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 103 INVITE User-Agent: (Very nice Sip Registrar Server) Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS Content-Type: application/sdp Content-Length: 202 v=0 o=username 1159004092 1159004092 IN IP4 80.239.235.174 s=SIP Call c=IN IP4 80.239.235.174 t=0 0 m=audio 58012 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 183 Session progress (28) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport (63) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=cb0078c24509605282a20 (68) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: sip:004989758585@194.120.0.203:5060 (46) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 103 INVITE (16) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: (Very nice Sip Registrar Server) (44) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS (45) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Content-Type: application/sdp (29) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Length: 202 (19) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: (0) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: v=0 (3) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: o=username 1159004092 1159004092 IN IP4 80.239.235.174 (53) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: s=SIP Call (10) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: c=IN IP4 80.239.235.174 (23) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: t=0 0 (5) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: m=audio 58012 RTP/AVP 0 101 (27) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=ptime:20 (10) --- (11 headers 9 lines)--- Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:1463 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' Request 103: Found Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:9601 handle_response_invite: SIP response 183 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 80.239.235.174:58012 Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3621 process_sdp: Peer audio RTP is at port 80.239.235.174:58012 Found description format PCMU Found description format telephone-event Capabilities: us - 0x1e (gsm|ulaw|alaw|g726), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 23 11:34:52 DEBUG[4665]: chan_sip.c:3716 process_sdp: Oooh, we need to change our formats since our peer supports only 0x4 (ulaw) and not 0x2 (gsm) Sep 23 11:34:52 DEBUG[4665]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to read format slin Sep 23 11:34:52 DEBUG[4665]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to write format slin -- SIP/out_provider-081c5058 is making progress passing it to SIP/210-081c90e0 We're at 192.168.2.100 port 10044 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x10 (g726) to SDP Adding codec 0x400 (ilbc) to SDP Transmitting (no NAT) to 192.168.2.210:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK3ea73bb287079257;received=192.168.2.210 From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 To: ;tag=as14e971e7 Call-ID: b2d83623cd133fed@192.168.2.210 CSeq: 17113 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 284 v=0 o=root 4642 4642 IN IP4 192.168.2.100 s=session c=IN IP4 192.168.2.100 t=0 0 m=audio 10044 RTP/AVP 0 8 18 2 97 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=silenceSupp:off - - - - --- Sep 23 11:34:52 DEBUG[4824]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw Sep 23 11:34:52 DEBUG[4824]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE ipaddr = '127.0.0.1' AND port = '37095' Sep 23 11:34:57 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:34:57 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (50/1159004047/1159004097)! Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:357 update_mysql: MySQL RealTime: Update SQL: UPDATE iax_buddies SET ipaddr = '127.0.0.1', port = '37095', regseconds = '1159004097' WHERE name = '310' Sep 23 11:34:57 DEBUG[4658]: res_config_mysql.c:371 update_mysql: MySQL RealTime: Updated 1 rows on table: iax_buddies Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004097/1159004097)! Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004097/1159004097)! Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:34:57 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:34:57 DEBUG[4844]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:34:57 DEBUG[4845]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:34:57 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:34:57 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004097/1159004097)! Sep 23 11:34:57 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 <-- SIP read from 194.120.0.203:5060: SIP/2.0 200 Ok Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport From: "Grandstream Bt101" ;tag=as333d6792 To: ;tag=cb0078c24509605282a20 Contact: sip:004989758585@194.120.0.203:5060 Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 103 INVITE User-Agent: (Very nice Sip Registrar Server) Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS Content-Type: application/sdp Content-Length: 202 v=0 o=username 1159004099 1159004099 IN IP4 80.239.235.174 s=SIP Call c=IN IP4 80.239.235.174 t=0 0 m=audio 58012 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 200 Ok (14) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK748d18c3;rport (63) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=cb0078c24509605282a20 (68) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: sip:004989758585@194.120.0.203:5060 (46) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 103 INVITE (16) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: (Very nice Sip Registrar Server) (44) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS (45) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Content-Type: application/sdp (29) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Length: 202 (19) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: (0) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: v=0 (3) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: o=username 1159004099 1159004099 IN IP4 80.239.235.174 (53) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: s=SIP Call (10) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: c=IN IP4 80.239.235.174 (23) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: t=0 0 (5) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: m=audio 58012 RTP/AVP 0 101 (27) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3414 parse_request: Line: a=ptime:20 (10) --- (11 headers 9 lines)--- Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:1388 __sip_ack: Acked pending invite 103 Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' of Request 103: Match Found Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:9601 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 80.239.235.174:58012 Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3621 process_sdp: Peer audio RTP is at port 80.239.235.174:58012 Found description format PCMU Found description format telephone-event Capabilities: us - 0x1e (gsm|ulaw|alaw|g726), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:6152 build_route: build_route: Contact hop: sip:004989758585@194.120.0.203:5060 list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 194.120.0.203, port 5060 Transmitting (NAT) to 194.120.0.203:5060: ACK sip:004989758585@194.120.0.203:5060 SIP/2.0 Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK76057ca8;rport From: "Grandstream Bt101" ;tag=as333d6792 To: ;tag=cb0078c24509605282a20 Contact: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/out_provider-081c5058 answered SIP/210-081c90e0 Sep 23 11:34:59 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/210-081c90e0 to read format ulaw Sep 23 11:34:59 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to write format ulaw Sep 23 11:34:59 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/out_provider-081c5058 to read format ulaw Sep 23 11:34:59 DEBUG[4824]: channel.c:2409 set_format: Set channel SIP/210-081c90e0 to write format ulaw Sep 23 11:34:59 DEBUG[4824]: chan_sip.c:2555 sip_answer: sip_answer(SIP/210-081c90e0) We're at 192.168.2.100 port 10044 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x10 (g726) to SDP Adding codec 0x400 (ilbc) to SDP Reliably Transmitting (no NAT) to 192.168.2.210:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK3ea73bb287079257;received=192.168.2.210 From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 To: ;tag=as14e971e7 Call-ID: b2d83623cd133fed@192.168.2.210 CSeq: 17113 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 284 v=0 o=root 4642 4643 IN IP4 192.168.2.100 s=session c=IN IP4 192.168.2.100 t=0 0 m=audio 10044 RTP/AVP 0 8 18 2 97 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=silenceSupp:off - - - - --- Sep 23 11:34:59 DEBUG[4824]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #44 Sep 23 11:34:59 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer out_provider Sep 23 11:34:59 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for SIP/out_provider - state 2 (In use) Sep 23 11:34:59 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer 210 Sep 23 11:34:59 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for SIP/210 - state 2 (In use) Sep 23 11:34:59 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer 210 Sep 23 11:34:59 DEBUG[4852]: app_queue.c:490 changethread: Device 'SIP/out_provider' changed to state '2' (In use) but we don't care because they're not a member of any queue. Sep 23 11:34:59 DEBUG[4854]: app_queue.c:490 changethread: Device 'SIP/210' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Attempting native bridge of SIP/210-081c90e0 and SIP/out_provider-081c5058 <-- SIP read from 192.168.2.210:5060: ACK sip:872@192.168.2.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK133f23dd656d7346 From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 To: ;tag=as14e971e7 Contact: Proxy-Authorization: Digest username="210", realm="asterisk", algorithm=MD5, uri="sip:872@192.168.2.100", nonce="2baf1b56", response="b0c739c331364296834a73b37e96d8ed" Call-ID: b2d83623cd133fed@192.168.2.210 CSeq: 17113 ACK User-Agent: Grandstream BT100 1.0.6.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: ACK sip:872@192.168.2.100 SIP/2.0 (33) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK133f23dd656d7346 (61) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 (70) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=as14e971e7 (42) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: (32) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Proxy-Authorization: Digest username="210", realm="asterisk", algorithm=MD5, uri="sip:872@192.168.2.100", nonce="2baf1b56", response="b0c739c331364296834a73b37e96d8ed" (167) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: Call-ID: b2d83623cd133fed@192.168.2.210 (39) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: CSeq: 17113 ACK (15) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: User-Agent: Grandstream BT100 1.0.6.7 (37) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Max-Forwards: 70 (16) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: Content-Length: 0 (17) Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 12: (0) --- (12 headers 0 lines)--- Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:11178 handle_request: **** Received ACK (6) - Command in SIP ACK Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #44 Sep 23 11:34:59 DEBUG[4665]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'b2d83623cd133fed@192.168.2.210' of Response 17113: Match Found Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE ipaddr = '127.0.0.1' AND port = '37095' Sep 23 11:35:01 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (4/1159004097/1159004101)! Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:357 update_mysql: MySQL RealTime: Update SQL: UPDATE iax_buddies SET ipaddr = '127.0.0.1', port = '37095', regseconds = '1159004101' WHERE name = '310' Sep 23 11:35:01 DEBUG[4658]: res_config_mysql.c:371 update_mysql: MySQL RealTime: Updated 1 rows on table: iax_buddies Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004101/1159004101)! Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004101/1159004101)! Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:01 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:01 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:01 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004101/1159004101)! Sep 23 11:35:01 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:01 DEBUG[4861]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:35:01 DEBUG[4862]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <-- SIP read from 192.168.2.210:5060: BYE sip:872@192.168.2.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK704c619c46368f76 From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 To: ;tag=as14e971e7 Proxy-Authorization: Digest username="210", realm="asterisk", algorithm=MD5, uri="sip:872@192.168.2.100", nonce="2baf1b56", response="bd4f6fbe939f6a13ea0874666e33ef1c" Call-ID: b2d83623cd133fed@192.168.2.210 CSeq: 17114 BYE User-Agent: Grandstream BT100 1.0.6.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: BYE sip:872@192.168.2.100 SIP/2.0 (33) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK704c619c46368f76 (61) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 (70) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=as14e971e7 (42) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Proxy-Authorization: Digest username="210", realm="asterisk", algorithm=MD5, uri="sip:872@192.168.2.100", nonce="2baf1b56", response="bd4f6fbe939f6a13ea0874666e33ef1c" (167) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: b2d83623cd133fed@192.168.2.210 (39) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 17114 BYE (15) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: Grandstream BT100 1.0.6.7 (37) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Max-Forwards: 70 (16) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: Content-Length: 0 (17) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:11178 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.2.210 : 5060 (non-NAT) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:10832 handle_request_bye: Received bye, issuing owner hangup Transmitting (no NAT) to 192.168.2.210:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.210;branch=z9hG4bK704c619c46368f76;received=192.168.2.210 From: "Grandstream Bt101" ;tag=cecd46448d7b91f1 To: ;tag=as14e971e7 Call-ID: b2d83623cd133fed@192.168.2.210 CSeq: 17114 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- Sep 23 11:35:05 DEBUG[4824]: channel.c:3377 ast_generic_bridge: Didn't get a frame from channel: SIP/210-081c90e0 Sep 23 11:35:05 DEBUG[4824]: channel.c:3660 ast_channel_bridge: Bridge stops bridging channels SIP/210-081c90e0 and SIP/out_provider-081c5058 Sep 23 11:35:05 DEBUG[4824]: channel.c:1373 ast_hangup: Hanging up channel 'SIP/out_provider-081c5058' Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2425 sip_hangup: Hangup call SIP/out_provider-081c5058, SIP callid 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com) Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2433 sip_hangup: update_call_counter(004989758585) - decrement call limit counter Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2215 update_call_counter: Updating call counter for outgoing call Scheduling destruction of call '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' in 32000 ms set_destination: Parsing for address/port to send to set_destination: set destination to 194.120.0.203, port 5060 Reliably Transmitting (NAT) to 194.120.0.203:5060: BYE sip:004989758585@194.120.0.203:5060 SIP/2.0 Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK4d1b412e;rport From: "Grandstream Bt101" ;tag=as333d6792 To: ;tag=cb0078c24509605282a20 Contact: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Authorization: Digest username="username", realm="sipdiscount.com", algorithm=MD5, uri="sip:004989758585@194.120.0.203:5060", nonce="2904060112", response="e05c389e71c88b09e1ae87fe8f68b055", opaque="" Content-Length: 0 --- Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 Sep 23 11:35:05 DEBUG[4824]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Sep 23 11:35:05 DEBUG[4824]: pbx.c:2316 __ast_pbx_run: Spawn extension (internal_context,872,2) exited non-zero on 'SIP/210-081c90e0' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/210-081c90e0", "INFO Sprung zu extension h in Context internal_context") in new stack Sep 23 11:35:05 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/210-081c90e0", "INFO: CHANNEL ist SIP/210-081c90e0") in new stack Sep 23 11:35:05 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/210-081c90e0", "INFO: DIALSTATUS ist ANSWER") in new stack Sep 23 11:35:05 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/210-081c90e0", "INFO: HANGUPCAUSE ist 16") in new stack Sep 23 11:35:05 DEBUG[4824]: pbx.c:1677 pbx_extension_helper: Launching 'Hangup' -- Executing Hangup("SIP/210-081c90e0", "") in new stack Sep 23 11:35:05 DEBUG[4824]: pbx.c:2454 __ast_pbx_run: Spawn extension (internal_context,h,5) exited non-zero on 'SIP/210-081c90e0' Sep 23 11:35:05 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer out_provider Sep 23 11:35:05 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for SIP/out_provider - state 1 (Not in use) Sep 23 11:35:05 DEBUG[4824]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Sep 23 11:35:05 DEBUG[4824]: 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-09-23 11:34:51','\"Grandstream Bt101\" <210>','210','872','internal_context', 'SIP/210-081c90e0','SIP/out_provider-081c5058','Hangup','',14,6,'ANSWERED',3,'','') Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Grandstream Bt101" <210>' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '210' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '872' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'internal_context' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/210-081c90e0' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/out_provider-081c5058' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Hangup' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-09-23 11:34:51' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-09-23 11:34:59' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-09-23 11:35:05' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '14' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1159004091.0' Sep 23 11:35:05 DEBUG[4824]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Sep 23 11:35:05 DEBUG[4824]: channel.c:1373 ast_hangup: Hanging up channel 'SIP/210-081c90e0' Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2425 sip_hangup: Hangup call SIP/210-081c90e0, SIP callid b2d83623cd133fed@192.168.2.210) Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2433 sip_hangup: update_call_counter(210) - decrement call limit counter Sep 23 11:35:05 DEBUG[4824]: chan_sip.c:2215 update_call_counter: Updating call counter for incoming call Sep 23 11:35:05 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer 210 Sep 23 11:35:05 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for SIP/210 - state 1 (Not in use) Sep 23 11:35:05 DEBUG[4647]: chan_sip.c:11719 sip_devicestate: Checking device state for peer 210 Sep 23 11:35:05 DEBUG[4875]: app_queue.c:490 changethread: Device 'SIP/out_provider' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:35:05 DEBUG[4876]: app_queue.c:490 changethread: Device 'SIP/210' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <-- SIP read from 194.120.0.203:5060: SIP/2.0 200 Ok Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK4d1b412e;rport From: "Grandstream Bt101" ;tag=as333d6792 To: ;tag=cb0078c24509605282a20 Contact: sip:004989758585@194.120.0.203:5060 Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com CSeq: 104 BYE User-Agent: (Very nice Sip Registrar Server) Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS Content-Length: 0 Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 0: SIP/2.0 200 Ok (14) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 1: Via: SIP/2.0/UDP 84.187.5.229:5060;branch=z9hG4bK4d1b412e;rport (63) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 2: From: "Grandstream Bt101" ;tag=as333d6792 (68) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 3: To: ;tag=cb0078c24509605282a20 (68) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 4: Contact: sip:004989758585@194.120.0.203:5060 (46) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 5: Call-ID: 02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com (59) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 6: CSeq: 104 BYE (13) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 7: User-Agent: (Very nice Sip Registrar Server) (44) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 8: Allow: ACK,BYE,CANCEL,INVITE,REGISTER,OPTIONS (45) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 9: Content-Length: 0 (17) Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:3382 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 Sep 23 11:35:05 DEBUG[4665]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' of Request 104: Match Found Destroying call '02bcfec637a5b00069ad437364b3c829@sip.voipcheap.com' Destroying call 'b2d83623cd133fed@192.168.2.210' Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE ipaddr = '127.0.0.1' AND port = '37095' Sep 23 11:35:07 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4658]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 192.168.2.0 Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4658]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4658]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (6/1159004101/1159004107)! Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:357 update_mysql: MySQL RealTime: Update SQL: UPDATE iax_buddies SET ipaddr = '127.0.0.1', port = '37095', regseconds = '1159004107' WHERE name = '310' Sep 23 11:35:07 DEBUG[4658]: res_config_mysql.c:371 update_mysql: MySQL RealTime: Updated 1 rows on table: iax_buddies Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004107/1159004107)! Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004107/1159004107)! Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 Sep 23 11:35:07 DEBUG[4647]: devicestate.c:187 do_state_change: Changing state for IAX2/310 - state 1 (Not in use) Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9438 iax2_devicestate: Checking device state for device 310 Sep 23 11:35:07 DEBUG[4883]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:35:07 DEBUG[4884]: app_queue.c:490 changethread: Device 'IAX2/310' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. Sep 23 11:35:07 DEBUG[4647]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM iax_buddies WHERE name = '310' Sep 23 11:35:07 DEBUG[4647]: acl.c:199 ast_append_ha: 192.168.2.0/255.255.255.0/255.255.255.0 appended to acl for peer Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:2694 realtime_peer: realtime_peer: Registration for '310' still active (0/1159004107/1159004107)! Sep 23 11:35:07 DEBUG[4647]: chan_iax2.c:9446 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 310? addr=16777343, defaddr=0 maxms=0, lastms=0 ---------------------------------------------------------------------- eof ----------------------------------------------------------------------