[May 19 19:28:49] VERBOSE[2719] logger.c: [May 19 19:28:49] Asterisk Queue Logger restarted [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] <--- SIP read from 192.168.1.23:5061 ---> INVITE sip:3293456789@192.168.1.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK1f0418b6d679fb79 From: "TestCorp3" ;tag=d328926a535a417a To: Contact: Supported: replaces, timer, path Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18177 INVITE User-Agent: Grandstream GXP2010 1.2.1.4 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Type: application/sdp Content-Length: 266 v=0 o=testcorp3 8000 8000 IN IP4 192.168.1.23 s=SIP Call c=IN IP4 192.168.1.23 t=0 0 m=audio 10134 RTP/AVP 18 8 3 101 a=sendrecv a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 0: INVITE sip:3293456789@192.168.1.150 SIP/2.0 (43) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK1f0418b6d679fb79 (65) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 2: From: "TestCorp3" ;tag=d328926a535a417a (68) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 3: To: (34) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 4: Contact: (56) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 5: Supported: replaces, timer, path (32) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 6: Call-ID: f8b61e224112aaa6@192.168.1.23 (38) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 7: CSeq: 18177 INVITE (18) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 8: User-Agent: Grandstream GXP2010 1.2.1.4 (39) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 11: Content-Type: application/sdp (29) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 266 (19) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 13: (0) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: v=0 (3) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: o=testcorp3 8000 8000 IN IP4 192.168.1.23 (41) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: s=SIP Call (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: c=IN IP4 192.168.1.23 (21) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: t=0 0 (5) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: m=audio 10134 RTP/AVP 18 8 3 101 (32) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=sendrecv (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=ptime:20 (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=fmtp:101 0-11 (15) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] --- (13 headers 13 lines) --- [May 19 19:29:01] DEBUG[2666] chan_sip.c: Setting NAT on RTP to Off [May 19 19:29:01] DEBUG[2666] chan_sip.c: Allocating new SIP dialog for f8b61e224112aaa6@192.168.1.23 - INVITE (With RTP) [May 19 19:29:01] DEBUG[2666] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 19 19:29:01] DEBUG[2666] chan_sip.c: Begin: parsing SIP "Supported: replaces, timer, path" [May 19 19:29:01] DEBUG[2666] chan_sip.c: Found SIP option: -replaces- [May 19 19:29:01] DEBUG[2666] chan_sip.c: Matched SIP option: replaces [May 19 19:29:01] DEBUG[2666] chan_sip.c: Found SIP option: -timer- [May 19 19:29:01] DEBUG[2666] chan_sip.c: Matched SIP option: timer [May 19 19:29:01] DEBUG[2666] chan_sip.c: Found SIP option: -path- [May 19 19:29:01] DEBUG[2666] chan_sip.c: Matched SIP option: path [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Sending to 192.168.1.23 : 5061 (no NAT) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Using INVITE request as basis request - f8b61e224112aaa6@192.168.1.23 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Setting NAT on RTP to On [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] <--- Reliably Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK1f0418b6d679fb79;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as21fd838e Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18177 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="blabla.be", nonce="5101ba14" Content-Length: 0 <------------> [May 19 19:29:01] DEBUG[2666] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Scheduling destruction of SIP dialog 'f8b61e224112aaa6@192.168.1.23' in 32000 ms (Method: INVITE) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found user 'testcorp3' [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] <--- SIP read from 192.168.1.23:5061 ---> ACK sip:3293456789@192.168.1.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK1f0418b6d679fb79 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as21fd838e Contact: Supported: path Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18177 ACK User-Agent: Grandstream GXP2010 1.2.1.4 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 <-------------> [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 0: ACK sip:3293456789@192.168.1.150 SIP/2.0 (40) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK1f0418b6d679fb79 (65) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 2: From: "TestCorp3" ;tag=d328926a535a417a (68) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 3: To: ;tag=as21fd838e (49) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 4: Contact: (56) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 5: Supported: path (15) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 6: Call-ID: f8b61e224112aaa6@192.168.1.23 (38) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 7: CSeq: 18177 ACK (15) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 8: User-Agent: Grandstream GXP2010 1.2.1.4 (39) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 11: Content-Length: 0 (17) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 12: (0) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] --- (12 headers 0 lines) --- [May 19 19:29:01] DEBUG[2666] chan_sip.c: = Found Their Call ID: f8b61e224112aaa6@192.168.1.23 Their Tag d328926a535a417a Our tag: as21fd838e [May 19 19:29:01] DEBUG[2666] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 19 19:29:01] DEBUG[2666] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #77 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Stopping retransmission on 'f8b61e224112aaa6@192.168.1.23' of Response 18177: Match Found [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] <--- SIP read from 192.168.1.23:5061 ---> INVITE sip:3293456789@192.168.1.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152 From: "TestCorp3" ;tag=d328926a535a417a To: Contact: Supported: replaces, timer, path Proxy-Authorization: Digest username="testcorp3", realm="blabla.be", algorithm=MD5, uri="sip:3293456789@192.168.1.150", nonce="5101ba14", response="8d4ac284a68928722ca6020417818419" Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: Grandstream GXP2010 1.2.1.4 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Type: application/sdp Content-Length: 266 v=0 o=testcorp3 8000 8001 IN IP4 192.168.1.23 s=SIP Call c=IN IP4 192.168.1.23 t=0 0 m=audio 10134 RTP/AVP 18 8 3 101 a=sendrecv a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 0: INVITE sip:3293456789@192.168.1.150 SIP/2.0 (43) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152 (65) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 2: From: "TestCorp3" ;tag=d328926a535a417a (68) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 3: To: (34) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 4: Contact: (56) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 5: Supported: replaces, timer, path (32) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 6: Proxy-Authorization: Digest username="testcorp3", realm="blabla.be", algorithm=MD5, uri="sip:3293456789@192.168.1.150", nonce="5101ba14", response="8d4ac284a68928722ca6020417818419" (185) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 7: Call-ID: f8b61e224112aaa6@192.168.1.23 (38) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 8: CSeq: 18178 INVITE (18) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 9: User-Agent: Grandstream GXP2010 1.2.1.4 (39) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 10: Max-Forwards: 70 (16) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 13: Content-Length: 266 (19) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Header 14: (0) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: v=0 (3) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: o=testcorp3 8000 8001 IN IP4 192.168.1.23 (41) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: s=SIP Call (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: c=IN IP4 192.168.1.23 (21) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: t=0 0 (5) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: m=audio 10134 RTP/AVP 18 8 3 101 (32) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=sendrecv (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=ptime:20 (10) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Line: a=fmtp:101 0-11 (15) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] --- (14 headers 13 lines) --- [May 19 19:29:01] DEBUG[2666] chan_sip.c: = Found Their Call ID: f8b61e224112aaa6@192.168.1.23 Their Tag d328926a535a417a Our tag: as21fd838e [May 19 19:29:01] DEBUG[2666] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Sending to 192.168.1.23 : 5061 (NAT) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Using INVITE request as basis request - f8b61e224112aaa6@192.168.1.23 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Setting NAT on RTP to On [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found user 'testcorp3' [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing session-level SDP o=testcorp3 8000 8001 IN IP4 192.168.1.23... UNSUPPORTED. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.23... OK. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found RTP audio format 18 [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found RTP audio format 8 [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found RTP audio format 3 [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found RTP audio format 101 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found audio description format G729 for ID 18 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found audio description format PCMA for ID 8 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found audio description format GSM for ID 3 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Found audio description format telephone-event for ID 101 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 19 19:29:01] DEBUG[2666] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [May 19 19:29:01] DEBUG[2666] chan_sip.c: T38 state changed to 0 on channel [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Capabilities: us - 0x10a (gsm|alaw|g729), peer - audio=0x10a (gsm|alaw|g729)/video=0x0 (nothing), combined - 0x10a (gsm|alaw|g729) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Our T38 capability = (0), peer T38 capability (0), joint T38 capability (0) [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Peer audio RTP is at port 192.168.1.23:10134 [May 19 19:29:01] DEBUG[2666] chan_sip.c: We're settling with these formats: 0x10a (gsm|alaw|g729) [May 19 19:29:01] DEBUG[2666] chan_sip.c: Checking SIP call limits for device testcorp3 [May 19 19:29:01] DEBUG[2666] chan_sip.c: Updating call counter for incoming call [May 19 19:29:01] DEBUG[2666] chan_sip.c: Call from peer 'testcorp3' is 1 out of 2 [May 19 19:29:01] DEBUG[2666] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp3 [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:01] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp3 - state 2 (In use) [May 19 19:29:01] DEBUG[2664] app_queue.c: Device 'SIP/testcorp3' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] Looking for 3293456789 in from-TESTCORP (domain 192.168.1.150) [May 19 19:29:01] DEBUG[2666] chan_sip.c: *** Our native formats are 0x2 (gsm) [May 19 19:29:01] DEBUG[2666] chan_sip.c: *** Joint capabilities are 0x10a (gsm|alaw|g729) [May 19 19:29:01] DEBUG[2666] chan_sip.c: *** Our capabilities are 0x10a (gsm|alaw|g729) [May 19 19:29:01] DEBUG[2666] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [May 19 19:29:01] DEBUG[2666] chan_sip.c: This channel will not be able to handle video. [May 19 19:29:01] DEBUG[2666] chan_sip.c: build_route: Contact hop: [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] list_route: hop: [May 19 19:29:01] DEBUG[2666] chan_sip.c: SIP/testcorp3-00000004: New call is still down.... Trying... [May 19 19:29:01] VERBOSE[2666] logger.c: [May 19 19:29:01] <--- Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [May 19 19:29:01] DEBUG[2666] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp3 [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:01] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp3 - state 2 (In use) [May 19 19:29:01] DEBUG[2664] app_queue.c: Device 'SIP/testcorp3' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:01] DEBUG[2720] pbx.c: Launching 'Dial' [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] -- Executing [3293456789@from-TESTCORP:1] Dial("SIP/testcorp3-00000004", "SIP/testcorp1|10|r") in new stack [May 19 19:29:01] DEBUG[2720] chan_sip.c: Asked to create a SIP channel with formats: 0x2 (gsm) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Setting NAT on RTP to On [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** Our native formats are 0x2 (gsm) [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** Our capabilities are 0x10a (gsm|alaw|g729) [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** Our preferred formats from the incoming channel are 0x2 (gsm) [May 19 19:29:01] DEBUG[2720] chan_sip.c: This channel will not be able to handle video. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable DIALEDTIME. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable ANSWEREDTIME. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNAME. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNUMBER. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable DIALSTATUS. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable SIPCALLID. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable SIPUSERAGENT. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable SIPDOMAIN. [May 19 19:29:01] DEBUG[2720] channel.c: Not copying variable SIPURI. [May 19 19:29:01] DEBUG[2720] chan_sip.c: Outgoing Call for testcorp1 [May 19 19:29:01] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:01] DEBUG[2720] chan_sip.c: Call to peer 'testcorp1' is 1 out of 2 [May 19 19:29:01] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:01] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 6 (Ringing) [May 19 19:29:01] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '6' (Ringing) [May 19 19:29:01] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:01] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:01] DEBUG[2720] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [May 19 19:29:01] DEBUG[2720] chan_sip.c: ** Our capability: 0xa (gsm|alaw) Video flag: False [May 19 19:29:01] DEBUG[2720] chan_sip.c: ** Our prefcodec: 0x2 (gsm) [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] Audio is at 192.168.1.150 port 11572 [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] Adding codec 0x2 (gsm) to SDP [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] Adding codec 0x8 (alaw) to SDP [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] Adding non-codec 0x1 (telephone-event) to SDP [May 19 19:29:01] DEBUG[2720] chan_sip.c: -- Done with adding codecs to SDP [May 19 19:29:01] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=36) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Done building SDP. Settling with this capability: 0xa (gsm|alaw) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 0: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 (87) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport (64) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 2: From: "TestCorp3" ;tag=as338e6957 (62) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 3: To: (78) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 4: Contact: (38) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 5: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 (55) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:01 GMT (35) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 13: Content-Length: 265 (19) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Header 14: (0) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: v=0 (3) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: o=root 22262 22262 IN IP4 192.168.1.150 (39) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: s=session (9) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: c=IN IP4 192.168.1.150 (22) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: t=0 0 (5) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: m=audio 11572 RTP/AVP 3 8 101 (29) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=ptime:20 (10) [May 19 19:29:01] DEBUG[2720] chan_sip.c: Line: a=sendrecv (10) [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] Reliably Transmitting (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport From: "TestCorp3" ;tag=as338e6957 To: Contact: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11572 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:01] DEBUG[2720] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] -- Called testcorp1 [May 19 19:29:01] VERBOSE[2720] logger.c: [May 19 19:29:01] <--- Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [May 19 19:29:02] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #80 (1) INVITE - 5 [May 19 19:29:02] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #80)) [May 19 19:29:02] VERBOSE[2666] logger.c: [May 19 19:29:02] Retransmitting #1 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport From: "TestCorp3" ;tag=as338e6957 To: Contact: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11572 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:03] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #80 (2) INVITE - 5 [May 19 19:29:03] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #80)) [May 19 19:29:03] VERBOSE[2666] logger.c: [May 19 19:29:03] Retransmitting #2 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport From: "TestCorp3" ;tag=as338e6957 To: Contact: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11572 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:04] DEBUG[2666] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 0: OPTIONS sip:testcorp4@192.168.1.21:5060 SIP/2.0 (47) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK0688e4c6;rport (64) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as3ae20c59 (60) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 3: To: (37) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 4: Contact: (37) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150 (55) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:04 GMT (35) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:04] VERBOSE[2666] logger.c: [May 19 19:29:04] Reliably Transmitting (NAT) to 192.168.1.21:5060: OPTIONS sip:testcorp4@192.168.1.21:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK0688e4c6;rport From: "asterisk" ;tag=as3ae20c59 To: Contact: Call-ID: 1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150 CSeq: 102 OPTIONS User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:04 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 --- [May 19 19:29:04] DEBUG[2666] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:04] VERBOSE[2666] logger.c: [May 19 19:29:04] <--- SIP read from 192.168.1.21:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK0688e4c6;rport From: "asterisk" ;tag=as3ae20c59 To: ;tag=5907CC78-48C6FF75 CSeq: 102 OPTIONS Call-ID: 1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_300-UA/1.6.3.0067 Content-Length: 0 <-------------> [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK0688e4c6;rport (64) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as3ae20c59 (60) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 3: To: ;tag=5907CC78-48C6FF75 (59) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 4: CSeq: 102 OPTIONS (17) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150 (55) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 6: Contact: (42) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_300-UA/1.6.3.0067 (54) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 9: Content-Length: 0 (17) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 10: (0) [May 19 19:29:04] VERBOSE[2666] logger.c: [May 19 19:29:04] --- (10 headers 0 lines) --- [May 19 19:29:04] DEBUG[2666] chan_sip.c: = Found Their Call ID: 1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150 Their Tag Our tag: as3ae20c59 [May 19 19:29:04] DEBUG[2666] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #83 [May 19 19:29:04] DEBUG[2666] chan_sip.c: Stopping retransmission on '1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150' of Request 102: Match Found [May 19 19:29:04] VERBOSE[2666] logger.c: [May 19 19:29:04] Really destroying SIP dialog '1b92f4d811d4d49c58c356e476fac0a2@192.168.1.150' Method: OPTIONS [May 19 19:29:04] VERBOSE[2666] logger.c: [May 19 19:29:04] <--- SIP read from 192.168.1.23:5061 ---> <-------------> [May 19 19:29:04] DEBUG[2666] chan_sip.c: Header 0: (0) [May 19 19:29:04] DEBUG[2666] chan_sip.c: Line: (0) [May 19 19:29:05] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #80 (3) INVITE - 5 [May 19 19:29:05] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #80)) [May 19 19:29:05] VERBOSE[2666] logger.c: [May 19 19:29:05] Retransmitting #3 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport From: "TestCorp3" ;tag=as338e6957 To: Contact: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11572 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:09] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #80 (4) INVITE - 5 [May 19 19:29:09] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 8000 ms (t1 500 ms (Retrans id #80)) [May 19 19:29:09] VERBOSE[2666] logger.c: [May 19 19:29:09] Retransmitting #4 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK4c621b9c;rport From: "TestCorp3" ;tag=as338e6957 To: Contact: Call-ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11572 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] -- Nobody picked up in 10000 ms [May 19 19:29:11] DEBUG[2720] rtp.c: Channel '' has no RTP, not doing anything [May 19 19:29:11] DEBUG[2720] channel.c: Hanging up channel 'SIP/testcorp1-00000005' [May 19 19:29:11] DEBUG[2720] chan_sip.c: Hangup call SIP/testcorp1-00000005, SIP callid 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150) [May 19 19:29:11] DEBUG[2720] chan_sip.c: update_call_counter(testcorp1) - decrement call limit counter on hangup [May 19 19:29:11] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:11] DEBUG[2720] chan_sip.c: Call to peer 'testcorp1' removed from call limit 2 [May 19 19:29:11] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 1 (Not in use) [May 19 19:29:11] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '1' (Not in use) [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Hanging up channel in state Down (not UP) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Acked pending invite 102 [May 19 19:29:11] DEBUG[2720] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #80 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Stopping retransmission on '404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150' of Request 102: Match Found [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Scheduling destruction of SIP dialog '404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150' in 32000 ms (Method: INVITE) [May 19 19:29:11] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 1 (Not in use) [May 19 19:29:11] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '1' (Not in use) [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2720] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [May 19 19:29:11] DEBUG[2720] pbx.c: Launching 'Queue' [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] -- Executing [3293456789@from-TESTCORP:2] Queue("SIP/testcorp3-00000004", "testcorpq1||||10") in new stack [May 19 19:29:11] DEBUG[2720] app_queue.c: NO QUEUE_PRIO variable found. Using default. [May 19 19:29:11] DEBUG[2720] app_queue.c: queue: testcorpq1, options: , url: , announce: , expires: 1274290161, priority: 0 [May 19 19:29:11] DEBUG[2720] res_config_mysql.c: MySQL RealTime: Everything is fine. [May 19 19:29:11] DEBUG[2720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queues WHERE name = 'testcorpq1' [May 19 19:29:11] DEBUG[2720] res_config_mysql.c: MySQL RealTime: Everything is fine. [May 19 19:29:11] DEBUG[2720] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = 'testcorpq1' ORDER BY interface [May 19 19:29:11] DEBUG[2720] app_queue.c: Queue 'testcorpq1' Join, Channel 'SIP/testcorp3-00000004', Position '1' [May 19 19:29:11] DEBUG[2720] channel.c: Prodding channel 'SIP/testcorp3-00000004' [May 19 19:29:11] DEBUG[2720] chan_sip.c: Setting framing from config on incoming call [May 19 19:29:11] DEBUG[2720] chan_sip.c: ** Our capability: 0x10a (gsm|alaw|g729) Video flag: True [May 19 19:29:11] DEBUG[2720] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Audio is at 192.168.1.150 port 11518 [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding codec 0x2 (gsm) to SDP [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding codec 0x8 (alaw) to SDP [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding codec 0x100 (g729) to SDP [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding non-codec 0x1 (telephone-event) to SDP [May 19 19:29:11] DEBUG[2720] chan_sip.c: -- Done with adding codecs to SDP [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Done building SDP. Settling with this capability: 0x10a (gsm|alaw|g729) [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] <--- Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Type: application/sdp Content-Length: 312 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11518 RTP/AVP 3 8 18 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] -- Started music on hold, class 'default', on SIP/testcorp3-00000004 [May 19 19:29:11] DEBUG[2720] channel.c: Scheduling timer at 160 sample intervals [May 19 19:29:11] DEBUG[2720] app_queue.c: There is 1 available member. [May 19 19:29:11] DEBUG[2720] app_queue.c: It's our turn (SIP/testcorp3-00000004). [May 19 19:29:11] DEBUG[2720] app_queue.c: SIP/testcorp3-00000004 is trying to call a queue member. [May 19 19:29:11] DEBUG[2720] app_queue.c: (Parallel) Trying 'SIP/testcorpt2' with metric 0 [May 19 19:29:11] DEBUG[2720] app_queue.c: SIP/testcorpt2 in use, can't receive call [May 19 19:29:11] DEBUG[2720] app_queue.c: (Parallel) Trying 'SIP/testcorpt1' with metric 0 [May 19 19:29:11] DEBUG[2720] app_queue.c: SIP/testcorpt1 in use, can't receive call [May 19 19:29:11] DEBUG[2720] app_queue.c: (Parallel) Trying 'SIP/testcorp1' with metric 0 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Asked to create a SIP channel with formats: 0x2 (gsm) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Setting NAT on RTP to On [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** Our native formats are 0x2 (gsm) [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** Our capabilities are 0x10a (gsm|alaw|g729) [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** Our preferred formats from the incoming channel are 0x2 (gsm) [May 19 19:29:11] DEBUG[2720] chan_sip.c: This channel will not be able to handle video. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable DIALSTATUS. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable DIALEDTIME. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable ANSWEREDTIME. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNAME. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNUMBER. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable SIPCALLID. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable SIPUSERAGENT. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable SIPDOMAIN. [May 19 19:29:11] DEBUG[2720] channel.c: Not copying variable SIPURI. [May 19 19:29:11] DEBUG[2720] chan_sip.c: Outgoing Call for testcorp1 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:11] DEBUG[2720] chan_sip.c: Call to peer 'testcorp1' is 1 out of 2 [May 19 19:29:11] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 6 (Ringing) [May 19 19:29:11] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '6' (Ringing) [May 19 19:29:11] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [May 19 19:29:11] DEBUG[2720] chan_sip.c: ** Our capability: 0xa (gsm|alaw) Video flag: False [May 19 19:29:11] DEBUG[2720] chan_sip.c: ** Our prefcodec: 0x2 (gsm) [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Audio is at 192.168.1.150 port 11526 [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding codec 0x2 (gsm) to SDP [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding codec 0x8 (alaw) to SDP [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Adding non-codec 0x1 (telephone-event) to SDP [May 19 19:29:11] DEBUG[2720] chan_sip.c: -- Done with adding codecs to SDP [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Done building SDP. Settling with this capability: 0xa (gsm|alaw) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 0: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 (87) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport (64) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 2: From: "TestCorp3" ;tag=as2ebae8a5 (62) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 3: To: (78) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 4: Contact: (38) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 5: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 (55) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:11 GMT (35) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 13: Content-Length: 265 (19) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Header 14: (0) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: v=0 (3) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: o=root 22262 22262 IN IP4 192.168.1.150 (39) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: s=session (9) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: c=IN IP4 192.168.1.150 (22) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: t=0 0 (5) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: m=audio 11526 RTP/AVP 3 8 101 (29) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=ptime:20 (10) [May 19 19:29:11] DEBUG[2720] chan_sip.c: Line: a=sendrecv (10) [May 19 19:29:11] VERBOSE[2720] logger.c: [May 19 19:29:11] Reliably Transmitting (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport From: "TestCorp3" ;tag=as2ebae8a5 To: Contact: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11526 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:11] DEBUG[2720] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:11] DEBUG[2720] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:11] DEBUG[2720] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:11] DEBUG[2720] channel.c: Set channel SIP/testcorp3-00000004 to write format slin [May 19 19:29:11] DEBUG[2720] res_musiconhold.c: SIP/testcorp3-00000004 Opened file 6 '/var/lib/asterisk/moh/reno_project-system' [May 19 19:29:11] DEBUG[2720] rtp.c: Ooh, format changed from unknown to gsm [May 19 19:29:11] DEBUG[2720] rtp.c: Created smoother: format: 2 ms: 20 len: 33 [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Generator got voice, switching to phase locked mode [May 19 19:29:11] DEBUG[2720] channel.c: Scheduling timer at 0 sample intervals [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:11] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #88 (1) INVITE - 5 [May 19 19:29:12] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #88)) [May 19 19:29:12] VERBOSE[2666] logger.c: [May 19 19:29:12] Retransmitting #1 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport From: "TestCorp3" ;tag=as2ebae8a5 To: Contact: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11526 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:12] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #88 (2) INVITE - 5 [May 19 19:29:13] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #88)) [May 19 19:29:13] VERBOSE[2666] logger.c: [May 19 19:29:13] Retransmitting #2 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport From: "TestCorp3" ;tag=as2ebae8a5 To: Contact: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11526 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:13] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:14] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #88 (3) INVITE - 5 [May 19 19:29:15] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #88)) [May 19 19:29:15] VERBOSE[2666] logger.c: [May 19 19:29:15] Retransmitting #3 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport From: "TestCorp3" ;tag=as2ebae8a5 To: Contact: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11526 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:15] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:16] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:17] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:18] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #88 (4) INVITE - 5 [May 19 19:29:19] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 8000 ms (t1 500 ms (Retrans id #88)) [May 19 19:29:19] VERBOSE[2666] logger.c: [May 19 19:29:19] Retransmitting #4 (NAT) to my_pub_ip:5060: INVITE sip:testcorp1@my_pub_ip:5060;rinstance=78173ac2b45b24f5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK417f4ab0;rport From: "TestCorp3" ;tag=as2ebae8a5 To: Contact: Call-ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11526 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:19] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:20] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:21] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] -- Nobody picked up in 10000 ms [May 19 19:29:22] DEBUG[2720] channel.c: Hanging up channel 'SIP/testcorp1-00000006' [May 19 19:29:22] DEBUG[2720] chan_sip.c: Hangup call SIP/testcorp1-00000006, SIP callid 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150) [May 19 19:29:22] DEBUG[2720] chan_sip.c: update_call_counter(testcorp1) - decrement call limit counter on hangup [May 19 19:29:22] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:22] DEBUG[2720] chan_sip.c: Call to peer 'testcorp1' removed from call limit 2 [May 19 19:29:22] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:22] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 1 (Not in use) [May 19 19:29:22] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '1' (Not in use) [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:22] DEBUG[2720] chan_sip.c: Hanging up channel in state Down (not UP) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Acked pending invite 102 [May 19 19:29:22] DEBUG[2720] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88 [May 19 19:29:22] DEBUG[2720] chan_sip.c: Stopping retransmission on '7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150' of Request 102: Match Found [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Scheduling destruction of SIP dialog '7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150' in 32000 ms (Method: INVITE) [May 19 19:29:22] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp1 [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:22] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp1 - state 1 (Not in use) [May 19 19:29:22] DEBUG[2664] app_queue.c: Device 'SIP/testcorp1' changed to state '1' (Not in use) [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp1 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp1 [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] -- Stopped music on hold on SIP/testcorp3-00000004 [May 19 19:29:22] DEBUG[2720] channel.c: Set channel SIP/testcorp3-00000004 to write format gsm [May 19 19:29:22] DEBUG[2720] channel.c: Scheduling timer at 0 sample intervals [May 19 19:29:22] DEBUG[2720] app_queue.c: Queue 'testcorpq1' Leave, Channel 'SIP/testcorp3-00000004' [May 19 19:29:22] DEBUG[2720] pbx.c: Launching 'Ringing' [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] -- Executing [3293456789@from-TESTCORP:3] Ringing("SIP/testcorp3-00000004", "") in new stack [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] <--- Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [May 19 19:29:22] DEBUG[2720] pbx.c: Launching 'Dial' [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] -- Executing [3293456789@from-TESTCORP:4] Dial("SIP/testcorp3-00000004", "SIP/testcorp2|10|r") in new stack [May 19 19:29:22] DEBUG[2720] chan_sip.c: Asked to create a SIP channel with formats: 0x2 (gsm) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Setting NAT on RTP to On [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** Our native formats are 0x2 (gsm) [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** Our capabilities are 0x10a (gsm|alaw|g729) [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** Our preferred formats from the incoming channel are 0x2 (gsm) [May 19 19:29:22] DEBUG[2720] chan_sip.c: This channel will not be able to handle video. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable DIALEDTIME. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable ANSWEREDTIME. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNAME. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable DIALEDPEERNUMBER. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable DIALSTATUS. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable QUEUESTATUS. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable SIPCALLID. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable SIPUSERAGENT. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable SIPDOMAIN. [May 19 19:29:22] DEBUG[2720] channel.c: Not copying variable SIPURI. [May 19 19:29:22] DEBUG[2720] chan_sip.c: Outgoing Call for testcorp2 [May 19 19:29:22] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:22] DEBUG[2720] chan_sip.c: Call to peer 'testcorp2' is 1 out of 2 [May 19 19:29:22] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp2 [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:22] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp2 - state 6 (Ringing) [May 19 19:29:22] DEBUG[2664] app_queue.c: Device 'SIP/testcorp2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 19 19:29:22] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:22] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:22] DEBUG[2720] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [May 19 19:29:22] DEBUG[2720] chan_sip.c: ** Our capability: 0xa (gsm|alaw) Video flag: False [May 19 19:29:22] DEBUG[2720] chan_sip.c: ** Our prefcodec: 0x2 (gsm) [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Audio is at 192.168.1.150 port 11500 [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Adding codec 0x2 (gsm) to SDP [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Adding codec 0x8 (alaw) to SDP [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Adding non-codec 0x1 (telephone-event) to SDP [May 19 19:29:22] DEBUG[2720] chan_sip.c: -- Done with adding codecs to SDP [May 19 19:29:22] DEBUG[2720] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=40) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Done building SDP. Settling with this capability: 0xa (gsm|alaw) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 0: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 (87) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport (64) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 2: From: "TestCorp3" ;tag=as09073a46 (62) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 3: To: (78) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 4: Contact: (38) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 5: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 (55) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:22 GMT (35) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 13: Content-Length: 265 (19) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Header 14: (0) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: v=0 (3) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: o=root 22262 22262 IN IP4 192.168.1.150 (39) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: s=session (9) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: c=IN IP4 192.168.1.150 (22) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: t=0 0 (5) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: m=audio 11500 RTP/AVP 3 8 101 (29) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=ptime:20 (10) [May 19 19:29:22] DEBUG[2720] chan_sip.c: Line: a=sendrecv (10) [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] Reliably Transmitting (NAT) to my_pub_ip:1030: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport From: "TestCorp3" ;tag=as09073a46 To: Contact: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11500 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:22] DEBUG[2720] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] -- Called testcorp2 [May 19 19:29:22] VERBOSE[2720] logger.c: [May 19 19:29:22] <--- Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [May 19 19:29:23] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #93 (1) INVITE - 5 [May 19 19:29:23] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #93)) [May 19 19:29:23] VERBOSE[2666] logger.c: [May 19 19:29:23] Retransmitting #1 (NAT) to my_pub_ip:1030: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport From: "TestCorp3" ;tag=as09073a46 To: Contact: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11500 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:24] VERBOSE[2666] logger.c: [May 19 19:29:24] <--- SIP read from 192.168.1.26:5060 ---> <-------------> [May 19 19:29:24] DEBUG[2666] chan_sip.c: Header 0: (0) [May 19 19:29:24] DEBUG[2666] chan_sip.c: Line: (0) [May 19 19:29:24] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #93 (2) INVITE - 5 [May 19 19:29:24] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #93)) [May 19 19:29:24] VERBOSE[2666] logger.c: [May 19 19:29:24] Retransmitting #2 (NAT) to my_pub_ip:1030: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport From: "TestCorp3" ;tag=as09073a46 To: Contact: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11500 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:24] VERBOSE[2666] logger.c: [May 19 19:29:24] <--- SIP read from 192.168.1.23:5061 ---> <-------------> [May 19 19:29:24] DEBUG[2666] chan_sip.c: Header 0: (0) [May 19 19:29:24] DEBUG[2666] chan_sip.c: Line: (0) [May 19 19:29:26] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #93 (3) INVITE - 5 [May 19 19:29:26] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #93)) [May 19 19:29:26] VERBOSE[2666] logger.c: [May 19 19:29:26] Retransmitting #3 (NAT) to my_pub_ip:1030: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport From: "TestCorp3" ;tag=as09073a46 To: Contact: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11500 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:28] VERBOSE[2666] logger.c: [May 19 19:29:28] <--- SIP read from 192.168.1.28:5060 ---> <-------------> [May 19 19:29:28] DEBUG[2666] chan_sip.c: Header 0: (0) [May 19 19:29:28] DEBUG[2666] chan_sip.c: Line: (0) [May 19 19:29:30] DEBUG[2666] chan_sip.c: SIP TIMER: Rescheduling retransmission #93 (4) INVITE - 5 [May 19 19:29:30] DEBUG[2666] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 8000 ms (t1 500 ms (Retrans id #93)) [May 19 19:29:30] VERBOSE[2666] logger.c: [May 19 19:29:30] Retransmitting #4 (NAT) to my_pub_ip:1030: INVITE sip:testcorp2@my_pub_ip:1030;rinstance=95144c7abb3fad1e;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7b181b4b;rport From: "TestCorp3" ;tag=as09073a46 To: Contact: Call-ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 CSeq: 102 INVITE User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 22262 22262 IN IP4 192.168.1.150 s=session c=IN IP4 192.168.1.150 t=0 0 m=audio 11500 RTP/AVP 3 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 19 19:29:32] VERBOSE[2720] logger.c: [May 19 19:29:32] -- Nobody picked up in 10000 ms [May 19 19:29:32] DEBUG[2720] rtp.c: Channel '' has no RTP, not doing anything [May 19 19:29:32] DEBUG[2720] channel.c: Hanging up channel 'SIP/testcorp2-00000007' [May 19 19:29:32] DEBUG[2720] chan_sip.c: Hangup call SIP/testcorp2-00000007, SIP callid 60d4ef6a04faccf226f850804960acde@192.168.1.150) [May 19 19:29:32] DEBUG[2720] chan_sip.c: update_call_counter(testcorp2) - decrement call limit counter on hangup [May 19 19:29:32] DEBUG[2720] chan_sip.c: Updating call counter for outgoing call [May 19 19:29:32] DEBUG[2720] chan_sip.c: Call to peer 'testcorp2' removed from call limit 2 [May 19 19:29:32] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp2 [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:32] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp2 - state 1 (Not in use) [May 19 19:29:32] DEBUG[2664] app_queue.c: Device 'SIP/testcorp2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:32] DEBUG[2720] chan_sip.c: Hanging up channel in state Down (not UP) [May 19 19:29:32] DEBUG[2720] chan_sip.c: Acked pending invite 102 [May 19 19:29:32] DEBUG[2720] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #93 [May 19 19:29:32] DEBUG[2720] chan_sip.c: Stopping retransmission on '60d4ef6a04faccf226f850804960acde@192.168.1.150' of Request 102: Match Found [May 19 19:29:32] VERBOSE[2720] logger.c: [May 19 19:29:32] Scheduling destruction of SIP dialog '60d4ef6a04faccf226f850804960acde@192.168.1.150' in 32000 ms (Method: INVITE) [May 19 19:29:32] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp2 [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:32] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp2 - state 1 (Not in use) [May 19 19:29:32] DEBUG[2664] app_queue.c: Device 'SIP/testcorp2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp2 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp2 [May 19 19:29:32] DEBUG[2720] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [May 19 19:29:32] VERBOSE[2720] logger.c: [May 19 19:29:32] == Auto fallthrough, channel 'SIP/testcorp3-00000004' status is 'NOANSWER' [May 19 19:29:32] DEBUG[2720] channel.c: Soft-Hanging up channel 'SIP/testcorp3-00000004' [May 19 19:29:32] DEBUG[2720] channel.c: Hanging up channel 'SIP/testcorp3-00000004' [May 19 19:29:32] DEBUG[2720] chan_sip.c: Hangup call SIP/testcorp3-00000004, SIP callid f8b61e224112aaa6@192.168.1.23) [May 19 19:29:32] DEBUG[2720] chan_sip.c: update_call_counter(testcorp3) - decrement call limit counter on hangup [May 19 19:29:32] DEBUG[2720] chan_sip.c: Updating call counter for incoming call [May 19 19:29:32] DEBUG[2720] chan_sip.c: Call from peer 'testcorp3' removed from call limit 2 [May 19 19:29:32] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp3 [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:32] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp3 - state 1 (Not in use) [May 19 19:29:32] DEBUG[2664] app_queue.c: Device 'SIP/testcorp3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:32] DEBUG[2720] chan_sip.c: Hanging up channel in state Ring (not UP) [May 19 19:29:32] VERBOSE[2720] logger.c: [May 19 19:29:32] Scheduling destruction of SIP dialog 'f8b61e224112aaa6@192.168.1.23' in 32000 ms (Method: INVITE) [May 19 19:29:32] VERBOSE[2720] logger.c: [May 19 19:29:32] <--- Reliably Transmitting (NAT) to 192.168.1.23:5061 ---> SIP/2.0 603 Declined Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152;received=192.168.1.23 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 INVITE User-Agent: blabla Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <------------> [May 19 19:29:32] DEBUG[2720] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:32] DEBUG[2720] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. [May 19 19:29:32] DEBUG[2720] cdr_addon_mysql.c: 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 ('2010-05-19 19:29:01','\"TestCorp3\" ','testcorp3','3293456789','from-TESTCORP', 'SIP/testcorp3-00000004','SIP/testcorp2-00000007','Dial','SIP/testcorp2|10|r',31,0,'BUSY',3,'TESTCORPintern','') [May 19 19:29:32] DEBUG[2720] devicestate.c: Notification of state change to be queued on device/channel SIP/testcorp3 [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:32] DEBUG[2658] devicestate.c: Changing state for SIP/testcorp3 - state 1 (Not in use) [May 19 19:29:32] DEBUG[2664] app_queue.c: Device 'SIP/testcorp3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 19 19:29:32] DEBUG[2658] devicestate.c: No provider found, checking channel drivers for SIP - testcorp3 [May 19 19:29:32] DEBUG[2658] chan_sip.c: Checking device state for peer testcorp3 [May 19 19:29:32] VERBOSE[2666] logger.c: [May 19 19:29:32] <--- SIP read from 192.168.1.23:5061 ---> ACK sip:3293456789@192.168.1.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152 From: "TestCorp3" ;tag=d328926a535a417a To: ;tag=as2ba2b301 Contact: Supported: path Proxy-Authorization: Digest username="testcorp3", realm="blabla.be", algorithm=MD5, uri="sip:3293456789@192.168.1.150", nonce="5101ba14", response="8d4ac284a68928722ca6020417818419" Call-ID: f8b61e224112aaa6@192.168.1.23 CSeq: 18178 ACK User-Agent: Grandstream GXP2010 1.2.1.4 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 <-------------> [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 0: ACK sip:3293456789@192.168.1.150 SIP/2.0 (40) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.23:5061;branch=z9hG4bK414481300aa99152 (65) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 2: From: "TestCorp3" ;tag=d328926a535a417a (68) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 3: To: ;tag=as2ba2b301 (49) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 4: Contact: (56) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 5: Supported: path (15) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 6: Proxy-Authorization: Digest username="testcorp3", realm="blabla.be", algorithm=MD5, uri="sip:3293456789@192.168.1.150", nonce="5101ba14", response="8d4ac284a68928722ca6020417818419" (185) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 7: Call-ID: f8b61e224112aaa6@192.168.1.23 (38) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 8: CSeq: 18178 ACK (15) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 9: User-Agent: Grandstream GXP2010 1.2.1.4 (39) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 10: Max-Forwards: 70 (16) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:32] DEBUG[2666] chan_sip.c: Header 13: (0) [May 19 19:29:32] VERBOSE[2666] logger.c: [May 19 19:29:32] --- (13 headers 0 lines) --- [May 19 19:29:32] DEBUG[2666] chan_sip.c: = No match Their Call ID: 60d4ef6a04faccf226f850804960acde@192.168.1.150 Their Tag Our tag: as09073a46 [May 19 19:29:32] DEBUG[2666] chan_sip.c: = No match Their Call ID: 7a5e8b0a0d5eb9015bafacf00ded4492@192.168.1.150 Their Tag Our tag: as2ebae8a5 [May 19 19:29:32] DEBUG[2666] chan_sip.c: = No match Their Call ID: 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 Their Tag Our tag: as338e6957 [May 19 19:29:32] DEBUG[2666] chan_sip.c: = Found Their Call ID: f8b61e224112aaa6@192.168.1.23 Their Tag d328926a535a417a Our tag: as2ba2b301 [May 19 19:29:32] DEBUG[2666] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 19 19:29:32] DEBUG[2666] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #98 [May 19 19:29:32] DEBUG[2666] chan_sip.c: Stopping retransmission on 'f8b61e224112aaa6@192.168.1.23' of Response 18178: Match Found [May 19 19:29:34] DEBUG[2666] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 0: OPTIONS sip:sip.b-1.be SIP/2.0 (30) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7eee4726;rport (64) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as18c443a7 (60) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 3: To: (20) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 4: Contact: (37) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 73e6e9f962ab064a16396fa17f05423c@192.168.1.150 (55) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:34 GMT (35) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] Reliably Transmitting (no NAT) to 80.245.47.69:5060: OPTIONS sip:sip.b-1.be SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7eee4726;rport From: "asterisk" ;tag=as18c443a7 To: Contact: Call-ID: 73e6e9f962ab064a16396fa17f05423c@192.168.1.150 CSeq: 102 OPTIONS User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 --- [May 19 19:29:34] DEBUG[2666] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] <--- SIP read from 80.245.47.69:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7eee4726;rport From: "asterisk" ;tag=as18c443a7 To: Contact: Call-ID: 73e6e9f962ab064a16396fa17f05423c@192.168.1.150 CSeq: 102 OPTIONS User-agent: blabla Max-Forwards: 69 Date: Wed, 19 May 2010 17:29:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <-------------> [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7eee4726;rport (64) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as18c443a7 (60) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 3: To: (20) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 4: Contact: (37) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 73e6e9f962ab064a16396fa17f05423c@192.168.1.150 (55) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 7: User-agent: blabla (22) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 8: Max-Forwards: 69 (16) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:34 GMT (35) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 13: (0) [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] --- (13 headers 0 lines) --- [May 19 19:29:34] DEBUG[2666] chan_sip.c: = Found Their Call ID: 73e6e9f962ab064a16396fa17f05423c@192.168.1.150 Their Tag Our tag: as18c443a7 [May 19 19:29:34] DEBUG[2666] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #99 [May 19 19:29:34] DEBUG[2666] chan_sip.c: Stopping retransmission on '73e6e9f962ab064a16396fa17f05423c@192.168.1.150' of Request 102: Match Found [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] Really destroying SIP dialog '73e6e9f962ab064a16396fa17f05423c@192.168.1.150' Method: OPTIONS [May 19 19:29:34] DEBUG[2666] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 0: OPTIONS sip:sip.b-1.be SIP/2.0 (30) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7d026339;rport (64) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as6b604f36 (60) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 3: To: (20) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 4: Contact: (37) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 6890d3575420ac1d004a2b3d22f0330a@192.168.1.150 (55) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 7: User-Agent: blabla (22) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:34 GMT (35) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] Reliably Transmitting (no NAT) to 80.245.47.69:5060: OPTIONS sip:sip.b-1.be SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7d026339;rport From: "asterisk" ;tag=as6b604f36 To: Contact: Call-ID: 6890d3575420ac1d004a2b3d22f0330a@192.168.1.150 CSeq: 102 OPTIONS User-Agent: blabla Max-Forwards: 70 Date: Wed, 19 May 2010 17:29:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 --- [May 19 19:29:34] DEBUG[2666] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] <--- SIP read from 80.245.47.69:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7d026339;rport From: "asterisk" ;tag=as6b604f36 To: Contact: Call-ID: 6890d3575420ac1d004a2b3d22f0330a@192.168.1.150 CSeq: 102 OPTIONS User-agent: blabla Max-Forwards: 69 Date: Wed, 19 May 2010 17:29:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <-------------> [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.150:5060;branch=z9hG4bK7d026339;rport (64) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 2: From: "asterisk" ;tag=as6b604f36 (60) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 3: To: (20) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 4: Contact: (37) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 5: Call-ID: 6890d3575420ac1d004a2b3d22f0330a@192.168.1.150 (55) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 7: User-agent: blabla (22) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 8: Max-Forwards: 69 (16) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 9: Date: Wed, 19 May 2010 17:29:34 GMT (35) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 11: Supported: replaces (19) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 12: Content-Length: 0 (17) [May 19 19:29:34] DEBUG[2666] chan_sip.c: Header 13: (0) [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] --- (13 headers 0 lines) --- [May 19 19:29:34] DEBUG[2666] chan_sip.c: = Found Their Call ID: 6890d3575420ac1d004a2b3d22f0330a@192.168.1.150 Their Tag Our tag: as6b604f36 [May 19 19:29:34] DEBUG[2666] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #102 [May 19 19:29:34] DEBUG[2666] chan_sip.c: Stopping retransmission on '6890d3575420ac1d004a2b3d22f0330a@192.168.1.150' of Request 102: Match Found [May 19 19:29:34] VERBOSE[2666] logger.c: [May 19 19:29:34] Really destroying SIP dialog '6890d3575420ac1d004a2b3d22f0330a@192.168.1.150' Method: OPTIONS [May 19 19:29:43] DEBUG[2666] chan_sip.c: Auto destroying SIP dialog '404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150' [May 19 19:29:43] DEBUG[2666] chan_sip.c: Destroying SIP dialog 404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150 [May 19 19:29:43] VERBOSE[2666] logger.c: [May 19 19:29:43] Really destroying SIP dialog '404c6dc85a5555856b8fd8c62c297f1f@192.168.1.150' Method: INVITE [May 19 19:29:52] VERBOSE[2719] logger.c: [May 19 19:29:52] -- Remote UNIX connection disconnected