[Oct 4 19:15:40] Asterisk Ready. *CLI> [Oct 4 19:16:18] <-- SIP read from 192.168.1.123:5060: INVITE sip:1234@mydomain.tld SIP/2.0 Record-Route: Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 Max-Forwards: 69 Contact: To: "1234" From: ;tag=c574cd45 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Proxy-Authorization: Digest username="1111",realm="mydomain.tld",nonce="4523df7eaa5c2ad67da6de69e0f1b58c7995f9cb",uri="sip:1234@mydomain.tld",response="3b74ba810d76a9dc7c0c781773e823c5",algorithm=MD5 User-Agent: X-Lite release 1003l stamp 30942 Content-Length: 317 X-Max-Duration: 7200000 v=0 o=- 7 2 IN IP4 192.168.1.110 s=CounterPath eyeBeam 1.5 c=IN IP4 192.168.1.110 t=0 0 m=audio 53838 RTP/AVP 98 101 a=alt:1 1 : gKQZaBsN BiaqSRbY 192.168.1.110 53838 a=fmtp:101 0-15 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv a=x-rtp-session-id:4C09A0C4DA4A45EE897B3D8EBA4CF9D2 [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: INVITE sip:1234@mydomain.tld SIP/2.0 (39) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Record-Route: (54) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 (61) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 (99) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Max-Forwards: 69 (16) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: Contact: (45) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: To: "1234" (36) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: From: ;tag=c574cd45 (50) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 9: CSeq: 2 INVITE (14) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 11: Content-Type: application/sdp (29) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 12: Proxy-Authorization: Digest username="1111",realm="mydomain.tld",nonce="4523df7eaa5c2ad67da6de69e0f1b58c7995f9cb",uri="sip:1234@mydomain.tld",response="3b74ba810d76a9dc7c0c781773e823c5",algorithm=MD5 (210) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 13: User-Agent: X-Lite release 1003l stamp 30942 (44) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 14: Content-Length: 317 (19) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 15: X-Max-Duration: 7200000 (32) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 16: (0) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: v=0 (3) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: o=- 7 2 IN IP4 192.168.1.110 (29) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: s=CounterPath eyeBeam 1.5 (25) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.110 (23) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: t=0 0 (5) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: m=audio 53838 RTP/AVP 98 101 (28) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=alt:1 1 : gKQZaBsN BiaqSRbY 192.168.1.110 53838 (50) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=fmtp:101 0-15 (15) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=sendrecv (10) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=x-rtp-session-id:4C09A0C4DA4A45EE897B3D8EBA4CF9D2 (51) [Oct 4 19:16:18] --- (16 headers 12 lines) --- [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4168 sip_alloc: Allocating new SIP dialog for 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. - INVITE (With RTP) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:14152 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 4 19:16:18] Sending to 192.168.1.123 : 5060 (no NAT) [Oct 4 19:16:18] Using INVITE request as basis request - 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. [Oct 4 19:16:18] Found peer 'ser' [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:8876 check_user_full: Setting NAT on RTP to On [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:8880 check_user_full: Setting NAT on VRTP to On [Oct 4 19:16:18] Found RTP audio format 98 [Oct 4 19:16:18] Found RTP audio format 101 [Oct 4 19:16:18] Peer audio RTP is at port 192.168.1.110:53838 [Oct 4 19:16:18] Got unsupported a:fmtp in SDP offer [Oct 4 19:16:18] Found description format iLBC for ID 98 [Oct 4 19:16:18] Found description format telephone-event for ID 101 [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4921 process_sdp: T38 state changed to 0 on channel [Oct 4 19:16:18] Capabilities: us - 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p), peer - audio=0x400 (ilbc)/video=0x0 (nothing), combined - 0x400 (ilbc) [Oct 4 19:16:18] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Oct 4 19:16:18] Peer audio RTP is at port 192.168.1.110:53838 [Oct 4 19:16:18] Peer video RTP is at port 192.168.1.110:19716 [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4991 process_sdp: We're settling with these formats: 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:12959 handle_request_invite: Checking SIP call limits for device [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:2897 update_call_counter: Updating call counter for incoming call [Oct 4 19:16:18] Looking for 1234 in pre-process (domain mydomain.tld) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:3663 sip_new: *** Our native formats are 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:3664 sip_new: *** Joint capabilities are 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:3665 sip_new: *** Our capabilities are 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:3666 sip_new: *** AST_CODEC_CHOOSE formats are 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:3689 sip_new: This channel will not be able to handle video. [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:7658 build_route: build_route: Record-Route hop: [Oct 4 19:16:18] list_route: hop: [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:13030 handle_request_invite: SIP/mydomain.tld-096aa440: New call is still down.... Trying... [Oct 4 19:16:18] Transmitting (NAT) to 192.168.1.123:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0;received=192.168.1.123 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 From: ;tag=c574cd45 To: "1234" Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Oct 4 19:16:18] DEBUG[28237]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/mydomain.tld-096aa440 [Oct 4 19:16:18] DEBUG[28216]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - mydomain.tld [Oct 4 19:16:18] DEBUG[28216]: chan_sip.c:14741 sip_devicestate: Checking device state for peer mydomain.tld [Oct 4 19:16:18] DEBUG[28216]: devicestate.c:287 do_state_change: Changing state for SIP/mydomain.tld - state 4 (Invalid) [Oct 4 19:16:18] DEBUG[28247]: app_queue.c:546 changethread: Device 'SIP/mydomain.tld' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Oct 4 19:16:18] DEBUG[28246]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Oct 4 19:16:18] -- Executing [1234@pre-process:1] SIPAddHeader("SIP/mydomain.tld-096aa440", "X-Test-Header1: test1") in new stack [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:16487 sip_addheader: SIP Header added "X-Test-Header1: test1" as _SIPADDHEADER01 [Oct 4 19:16:18] DEBUG[28246]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Oct 4 19:16:18] -- Executing [1234@pre-process:2] SIPAddHeader("SIP/mydomain.tld-096aa440", "X-Test-Header2:") in new stack [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:16487 sip_addheader: SIP Header added "X-Test-Header2:" as _SIPADDHEADER02 [Oct 4 19:16:18] DEBUG[28246]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' [Oct 4 19:16:18] -- Executing [1234@pre-process:3] Dial("SIP/mydomain.tld-096aa440", "SIP/2222@ser") in new stack [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:14799 sip_request_call: Asked to create a SIP channel with formats: 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:2533 create_addr_from_peer: Setting NAT on RTP to On [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:2540 create_addr_from_peer: Setting NAT on VRTP to On [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3663 sip_new: *** Our native formats are 0x100 (g729) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3664 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3665 sip_new: *** Our capabilities are 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3666 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3668 sip_new: *** Our preferred formats from the incoming channel are 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:3689 sip_new: This channel will not be able to handle video. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-3. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER02. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-2. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-1. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable VM_GENERIC_NUM. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable VM_NUM. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable DEFAULT_LANGUAGE. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable GLOBAL_MAX_DURATION. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable GLOBAL_NOANS_TIMEOUT. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable MAX_LOOP. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable DEFAULT_COUNTRY_CODE. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3132 ast_channel_inherit_variables: Copying soft-transferable variable SERVICE_PROVIDER. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 4 19:16:18] DEBUG[28246]: channel.c:3145 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:2737 sip_call: Outgoing Call for 2222 [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:2897 update_call_counter: Updating call counter for outgoing call [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:2745 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:6562 transmit_invite: Adding SIP Header "X-Test-Header2" with content :: [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:6562 transmit_invite: Adding SIP Header "X-Test-Header1" with content :test1: [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:5900 add_sdp: ** Our capability: 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) Video flag: False [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:5901 add_sdp: ** Our prefcodec: 0x400 (ilbc) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:5914 add_sdp: This call needs video offers! [Oct 4 19:16:18] Video is at 192.168.1.124 port 15776 [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:5950 add_sdp: ** No compatible video codecs... Disabling video. [Oct 4 19:16:18] Audio is at 192.168.1.124 port 18136 [Oct 4 19:16:18] Adding codec 0x400 (ilbc) to SDP [Oct 4 19:16:18] Adding codec 0x100 (g729) to SDP [Oct 4 19:16:18] Adding codec 0x8 (alaw) to SDP [Oct 4 19:16:18] Adding codec 0x4 (ulaw) to SDP [Oct 4 19:16:18] Adding codec 0x2 (gsm) to SDP [Oct 4 19:16:18] Adding non-codec 0x1 (telephone-event) to SDP [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:6053 add_sdp: -- Done with adding codecs to SDP [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:6092 add_sdp: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 0: INVITE sip:2222@192.168.1.123 SIP/2.0 (45) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport (65) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 2: From: "1111" ;tag=as6fade99b (64) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 3: To: (36) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 4: Contact: (39) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 5: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld (57) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 6: CSeq: 102 INVITE (16) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 7: User-Agent: Asterisk (27) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 9: Remote-Party-ID: "1111" ;privacy=off;screen=no (82) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 10: Date: Wed, 04 Oct 2006 16:16:18 GMT (35) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 12: Supported: replaces (19) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 13: X-Test-Header2: (24) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 14: X-Test-Header1: test1 (26) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 15: Content-Type: application/sdp (29) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 16: Content-Length: 419 (19) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4388 parse_request: Header 17: (0) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: v=0 (3) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: o=root 28212 28212 IN IP4 192.168.1.124 (40) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: s=session (9) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.124 (23) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: t=0 0 (5) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: m=audio 18136 RTP/AVP 97 18 8 0 3 101 (37) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=fmtp:97 mode=30 (17) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=fmtp:18 annexb=no (19) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=ptime:20 (10) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=ptime:20 (10) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=ptime:20 (10) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=ptime:20 (10) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:4420 parse_request: Line: a=sendrecv (10) [Oct 4 19:16:18] Reliably Transmitting (NAT) to 192.168.1.123:5060: INVITE sip:2222@192.168.1.123 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport From: "1111" ;tag=as6fade99b To: Contact: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld CSeq: 102 INVITE User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "1111" ;privacy=off;screen=no Date: Wed, 04 Oct 2006 16:16:18 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-Test-Header2: X-Test-Header1: test1 Content-Type: application/sdp Content-Length: 419 v=0 o=root 28212 28212 IN IP4 192.168.1.124 s=session c=IN IP4 192.168.1.124 t=0 0 m=audio 18136 RTP/AVP 97 18 8 0 3 101 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=rtpmap:8 PCMA/8000 a=ptime:20 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:3 GSM/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Oct 4 19:16:18] DEBUG[28246]: chan_sip.c:1920 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #3 [Oct 4 19:16:18] -- Called 2222@ser [Oct 4 19:16:18] DEBUG[28246]: channel.c:2680 set_format: Set channel SIP/ser-096b1028 to read format slin [Oct 4 19:16:18] DEBUG[28246]: channel.c:2680 set_format: Set channel SIP/mydomain.tld-096aa440 to write format slin [Oct 4 19:16:18] <-- SIP read from 192.168.1.123:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 From: "1111" ;tag=as6fade99b To: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld CSeq: 102 INVITE Server: OpenSER (1.1.0-notls (i386/linux)) Content-Length: 0 [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: SIP/2.0 100 Trying (18) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 (70) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: From: "1111" ;tag=as6fade99b (64) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: To: (36) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld (57) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: Server: OpenSER (1.1.0-notls (i386/linux)) (50) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: Content-Length: 0 (17) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: (0) [Oct 4 19:16:18] --- (8 headers 0 lines) --- [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:2061 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #3 - INVITE (got response) [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:2070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '59c350bf100cf776001cb28e19599611@mydomain.tld' Request 102: Found [Oct 4 19:16:18] DEBUG[28237]: chan_sip.c:11308 handle_response_invite: SIP response 100 to standard invite [Oct 4 19:16:18] DEBUG[28246]: channel.c:2680 set_format: Set channel SIP/mydomain.tld-096aa440 to read format slin [Oct 4 19:16:18] DEBUG[28246]: channel.c:2680 set_format: Set channel SIP/ser-096b1028 to write format slin [Oct 4 19:16:19] <-- SIP read from 192.168.1.123:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 From: "1111" ;tag=as6fade99b To: ;tag=AF753314-B38 Date: Wed, 04 Oct 2006 16:16:18 GMT Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Contact: Record-Route: Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 285 v=0 o=CiscoSystemsSIP-GW-UserAgent 2143 1268 IN IP4 192.168.1.35 s=SIP Call c=IN IP4 192.168.1.35 t=0 0 m=audio 16822 RTP/AVP 18 101 c=IN IP4 192.168.1.35 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 (70) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: From: "1111" ;tag=as6fade99b (64) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: To: ;tag=AF753314-B38 (53) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Date: Wed, 04 Oct 2006 16:16:18 GMT (35) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld (57) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: CSeq: 102 INVITE (16) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER (97) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 9: Allow-Events: telephone-event (29) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 10: Contact: (45) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 11: Record-Route: (56) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 13: Content-Disposition: session;handling=required (46) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 14: Content-Length: 285 (19) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 15: (0) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: v=0 (3) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 2143 1268 IN IP4 192.168.1.35 (60) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: s=SIP Call (10) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.35 (21) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: t=0 0 (5) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: m=audio 16822 RTP/AVP 18 101 (28) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.35 (21) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=fmtp:18 annexb=no (19) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 4 19:16:19] --- (15 headers 12 lines) --- [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:2070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '59c350bf100cf776001cb28e19599611@mydomain.tld' Request 102: Found [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:11308 handle_response_invite: SIP response 183 to standard invite [Oct 4 19:16:19] Found RTP audio format 18 [Oct 4 19:16:19] Found RTP audio format 101 [Oct 4 19:16:19] Peer audio RTP is at port 192.168.1.35:16822 [Oct 4 19:16:19] Found description format G729 for ID 18 [Oct 4 19:16:19] Got unsupported a:fmtp in SDP offer [Oct 4 19:16:19] Found description format telephone-event for ID 101 [Oct 4 19:16:19] Got unsupported a:fmtp in SDP offer [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4921 process_sdp: T38 state changed to 0 on channel SIP/ser-096b1028 [Oct 4 19:16:19] Capabilities: us - 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Oct 4 19:16:19] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Oct 4 19:16:19] Peer audio RTP is at port 192.168.1.35:16822 [Oct 4 19:16:19] Peer video RTP is at port 192.168.1.35:19716 [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4991 process_sdp: We're settling with these formats: 0x100 (g729) [Oct 4 19:16:19] DEBUG[28237]: chan_sip.c:4998 process_sdp: We have an owner, now see if we need to change this call [Oct 4 19:16:19] -- SIP/ser-096b1028 is making progress passing it to SIP/mydomain.tld-096aa440 [Oct 4 19:16:19] DEBUG[28246]: chan_sip.c:6147 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 4 19:16:19] DEBUG[28246]: chan_sip.c:5900 add_sdp: ** Our capability: 0x400 (ilbc) Video flag: True [Oct 4 19:16:19] DEBUG[28246]: chan_sip.c:5901 add_sdp: ** Our prefcodec: 0x0 (nothing) [Oct 4 19:16:19] Audio is at 192.168.1.124 port 11094 [Oct 4 19:16:19] Adding codec 0x400 (ilbc) to SDP [Oct 4 19:16:19] Adding non-codec 0x1 (telephone-event) to SDP [Oct 4 19:16:19] DEBUG[28246]: chan_sip.c:6053 add_sdp: -- Done with adding codecs to SDP [Oct 4 19:16:19] DEBUG[28246]: chan_sip.c:6092 add_sdp: Done building SDP. Settling with this capability: 0x400 (ilbc) [Oct 4 19:16:19] Transmitting (NAT) to 192.168.1.123:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0;received=192.168.1.123 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 From: ;tag=c574cd45 To: "1234";tag=as4a2db593 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 253 v=0 o=root 28212 28212 IN IP4 192.168.1.124 s=session c=IN IP4 192.168.1.124 t=0 0 m=audio 11094 RTP/AVP 98 101 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Oct 4 19:16:19] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 132 bytes [Oct 4 19:16:19] DEBUG[28246]: rtp.c:2558 ast_rtp_write: Ooh, format changed from unknown to ilbc [Oct 4 19:16:19] DEBUG[28246]: rtp.c:2575 ast_rtp_write: Created smoother: format: 1024 ms: 30 len: 50 [Oct 4 19:16:19] DEBUG[28246]: rtp.c:2558 ast_rtp_write: Ooh, format changed from unknown to g729 [Oct 4 19:16:19] DEBUG[28246]: rtp.c:2575 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Oct 4 19:16:21] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 108 bytes [Oct 4 19:16:22] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes [Oct 4 19:16:23] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 108 bytes [Oct 4 19:16:25] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes [Oct 4 19:16:27] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 108 bytes [Oct 4 19:16:28] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes [Oct 4 19:16:29] DEBUG[28246]: rtp.c:808 ast_rtcp_read: Got RTCP report of 160 bytes [Oct 4 19:16:29] <-- SIP read from 192.168.1.123:5060: CANCEL sip:1234@mydomain.tld SIP/2.0 Max-Forwards: 10 Record-Route: Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 To: "1234" From: ;tag=c574cd45 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 CANCEL Proxy-Authorization: Digest username="1111",realm="mydomain.tld",nonce="4523df7eaa5c2ad67da6de69e0f1b58c7995f9cb",uri="sip:1234@mydomain.tld",response="46cd4af1bf6f2e734d6143967d1869fe",algorithm=MD5 User-Agent: X-Lite release 1003l stamp 30942 Content-Length: 0 [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: CANCEL sip:1234@mydomain.tld SIP/2.0 (39) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Max-Forwards: 10 (16) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: Record-Route: (54) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 (61) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 (99) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: To: "1234" (36) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: From: ;tag=c574cd45 (50) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: CSeq: 2 CANCEL (14) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 9: Proxy-Authorization: Digest username="1111",realm="mydomain.tld",nonce="4523df7eaa5c2ad67da6de69e0f1b58c7995f9cb",uri="sip:1234@mydomain.tld",response="46cd4af1bf6f2e734d6143967d1869fe",algorithm=MD5 (210) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 10: User-Agent: X-Lite release 1003l stamp 30942 (44) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 11: Content-Length: 0 (17) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 12: (0) [Oct 4 19:16:29] --- (12 headers 0 lines) --- [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:14152 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Oct 4 19:16:29] Sending to 192.168.1.123 : 5060 (NAT) [Oct 4 19:16:29] Reliably Transmitting (NAT) to 192.168.1.123:5060: SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0;received=192.168.1.123 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 From: ;tag=c574cd45 To: "1234";tag=as4a2db593 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:1920 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Oct 4 19:16:29] Transmitting (NAT) to 192.168.1.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0;received=192.168.1.123 Via: SIP/2.0/UDP 192.168.1.110:16396;branch=z9hG4bK-d87543-535ba26ea204a757-1--d87543-;rport=16396 Record-Route: From: ;tag=c574cd45 To: "1234";tag=as4a2db593 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 CANCEL User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Oct 4 19:16:29] DEBUG[28246]: rtp.c:1419 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Oct 4 19:16:29] DEBUG[28246]: channel.c:1558 ast_hangup: Hanging up channel 'SIP/ser-096b1028' [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:3198 sip_hangup: Hangup call SIP/ser-096b1028, SIP callid 59c350bf100cf776001cb28e19599611@mydomain.tld) [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:3205 sip_hangup: update_call_counter(2222) - decrement call limit counter on hangup [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:2897 update_call_counter: Updating call counter for outgoing call [Oct 4 19:16:29] Scheduling destruction of SIP dialog '59c350bf100cf776001cb28e19599611@mydomain.tld' in 32000 ms (Method: INVITE) [Oct 4 19:16:29] DEBUG[28246]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ser-096b1028 [Oct 4 19:16:29] DEBUG[28246]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Oct 4 19:16:29] DEBUG[28246]: pbx.c:2363 __ast_pbx_run: Spawn extension (pre-process,1234,3) exited non-zero on 'SIP/mydomain.tld-096aa440' [Oct 4 19:16:29] == Spawn extension (pre-process, 1234, 3) exited non-zero on 'SIP/mydomain.tld-096aa440' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1111' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1111' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1234' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'pre-process' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/mydomain.tld-096aa440' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/ser-096b1028' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/2222@ser' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-10-04 19:16:18' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-10-04 19:16:29' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '11' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '0' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1159978578.0' [Oct 4 19:16:29] DEBUG[28246]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Oct 4 19:16:29] DEBUG[28246]: channel.c:1558 ast_hangup: Hanging up channel 'SIP/mydomain.tld-096aa440' [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:3198 sip_hangup: Hangup call SIP/mydomain.tld-096aa440, SIP callid 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.) [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:3205 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:2897 update_call_counter: Updating call counter for incoming call [Oct 4 19:16:29] DEBUG[28246]: chan_sip.c:3218 sip_hangup: Hanging up channel in state Ring (not UP) [Oct 4 19:16:29] DEBUG[28246]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/mydomain.tld-096aa440 [Oct 4 19:16:29] <-- SIP read from 192.168.1.123:5060: ACK sip:1234@mydomain.tld SIP/2.0 Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 From: ;tag=c574cd45 Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. To: "1234";tag=as4a2db593 CSeq: 2 ACK User-Agent: OpenSER (1.1.0-notls (i386/linux)) Content-Length: 0 [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: ACK sip:1234@mydomain.tld SIP/2.0 (36) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.123;branch=z9hG4bK409a.3fac7f92.0 (61) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: From: ;tag=c574cd45 (50) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: Call-ID: 9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: To: "1234";tag=as4a2db593 (51) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: CSeq: 2 ACK (11) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: User-Agent: OpenSER (1.1.0-notls (i386/linux)) (54) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: Content-Length: 0 (17) [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: (0) [Oct 4 19:16:29] --- (8 headers 0 lines) --- [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:14152 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:2018 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Oct 4 19:16:29] DEBUG[28237]: chan_sip.c:2028 __sip_ack: Stopping retransmission on '9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.' of Response 2: Match Not Found [Oct 4 19:16:29] Really destroying SIP dialog '9016ce03855da623YjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.' Method: ACK [Oct 4 19:16:29] DEBUG[28216]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - ser [Oct 4 19:16:29] DEBUG[28216]: chan_sip.c:14741 sip_devicestate: Checking device state for peer ser [Oct 4 19:16:29] DEBUG[28216]: devicestate.c:287 do_state_change: Changing state for SIP/ser - state 1 (Not in use) [Oct 4 19:16:29] DEBUG[28216]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - mydomain.tld [Oct 4 19:16:29] DEBUG[28216]: chan_sip.c:14741 sip_devicestate: Checking device state for peer mydomain.tld [Oct 4 19:16:29] DEBUG[28216]: devicestate.c:287 do_state_change: Changing state for SIP/mydomain.tld - state 4 (Invalid) [Oct 4 19:16:29] DEBUG[28249]: app_queue.c:546 changethread: Device 'SIP/ser' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 4 19:16:29] DEBUG[28250]: app_queue.c:546 changethread: Device 'SIP/mydomain.tld' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Oct 4 19:16:42] <-- SIP read from 192.168.1.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 From: "1111" ;tag=as6fade99b To: ;tag=AF753314-B38 Date: Wed, 04 Oct 2006 16:16:18 GMT Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Contact: Record-Route: Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 285 v=0 o=CiscoSystemsSIP-GW-UserAgent 2143 1268 IN IP4 192.168.1.35 s=SIP Call c=IN IP4 192.168.1.35 t=0 0 m=audio 16822 RTP/AVP 18 101 c=IN IP4 192.168.1.35 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK1db8d06d;rport=5060 (70) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: From: "1111" ;tag=as6fade99b (64) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: To: ;tag=AF753314-B38 (53) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Date: Wed, 04 Oct 2006 16:16:18 GMT (35) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld (57) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: CSeq: 102 INVITE (16) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER (97) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 9: Allow-Events: telephone-event (29) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 10: Contact: (45) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 11: Record-Route: (56) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 13: Content-Disposition: session;handling=required (46) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 14: Content-Length: 285 (19) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 15: (0) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: v=0 (3) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 2143 1268 IN IP4 192.168.1.35 (60) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: s=SIP Call (10) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.35 (21) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: t=0 0 (5) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: m=audio 16822 RTP/AVP 18 101 (28) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: c=IN IP4 192.168.1.35 (21) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=fmtp:18 annexb=no (19) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4420 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 4 19:16:42] --- (15 headers 12 lines) --- [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:2010 __sip_ack: Acked pending invite 102 [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:2028 __sip_ack: Stopping retransmission on '59c350bf100cf776001cb28e19599611@mydomain.tld' of Request 102: Match Not Found [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:11308 handle_response_invite: SIP response 200 to standard invite [Oct 4 19:16:42] Found RTP audio format 18 [Oct 4 19:16:42] Found RTP audio format 101 [Oct 4 19:16:42] Peer audio RTP is at port 192.168.1.35:16822 [Oct 4 19:16:42] Found description format G729 for ID 18 [Oct 4 19:16:42] Got unsupported a:fmtp in SDP offer [Oct 4 19:16:42] Found description format telephone-event for ID 101 [Oct 4 19:16:42] Got unsupported a:fmtp in SDP offer [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4921 process_sdp: T38 state changed to 0 on channel [Oct 4 19:16:42] Capabilities: us - 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Oct 4 19:16:42] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Oct 4 19:16:42] Peer audio RTP is at port 192.168.1.35:16822 [Oct 4 19:16:42] Peer video RTP is at port 192.168.1.35:19716 [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4991 process_sdp: We're settling with these formats: 0x100 (g729) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:2897 update_call_counter: Updating call counter for outgoing call [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:7658 build_route: build_route: Record-Route hop: [Oct 4 19:16:42] list_route: hop: [Oct 4 19:16:42] set_destination: Parsing for address/port to send to [Oct 4 19:16:42] set_destination: set destination to 192.168.1.123, port 5060 [Oct 4 19:16:42] Transmitting (NAT) to 192.168.1.123:5060: ACK sip:2222@192.168.1.35:53019 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK7bd98d05;rport Route: From: "1111" ;tag=as6fade99b To: ;tag=AF753314-B38 Contact: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld CSeq: 102 ACK User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "1111" ;privacy=off;screen=no Content-Length: 0 --- [Oct 4 19:16:42] set_destination: Parsing for address/port to send to [Oct 4 19:16:42] set_destination: set destination to 192.168.1.123, port 5060 [Oct 4 19:16:42] Reliably Transmitting (NAT) to 192.168.1.123:5060: BYE sip:2222@192.168.1.35:53019 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK2d23c9cd;rport Route: From: "1111" ;tag=as6fade99b To: ;tag=AF753314-B38 Contact: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld CSeq: 103 BYE User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "1111" ;privacy=off;screen=no Content-Length: 0 --- [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:1920 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #9 [Oct 4 19:16:42] Scheduling destruction of SIP dialog '59c350bf100cf776001cb28e19599611@mydomain.tld' in 32000 ms (Method: INVITE) [Oct 4 19:16:42] <-- SIP read from 192.168.1.123:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK2d23c9cd;rport=5060 From: "1111" ;tag=as6fade99b To: ;tag=AF753314-B38 Date: Wed, 04 Oct 2006 16:16:42 GMT Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 103 BYE Reason: Q.850;cause=16 Content-Length: 0 [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.124:5060;branch=z9hG4bK2d23c9cd;rport=5060 (70) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 2: From: "1111" ;tag=as6fade99b (64) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 3: To: ;tag=AF753314-B38 (53) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 4: Date: Wed, 04 Oct 2006 16:16:42 GMT (35) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 5: Call-ID: 59c350bf100cf776001cb28e19599611@mydomain.tld (57) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 7: CSeq: 103 BYE (13) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 8: Reason: Q.850;cause=16 (22) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 9: Content-Length: 0 (17) [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:4388 parse_request: Header 10: (0) [Oct 4 19:16:42] --- (10 headers 0 lines) --- [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:2018 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 [Oct 4 19:16:42] DEBUG[28237]: chan_sip.c:2028 __sip_ack: Stopping retransmission on '59c350bf100cf776001cb28e19599611@mydomain.tld' of Request 103: Match Not Found [Oct 4 19:16:42] Really destroying SIP dialog '59c350bf100cf776001cb28e19599611@mydomain.tld' Method: INVITE *CLI> *CLI> stop now [Oct 4 19:16:57] Beginning asterisk shutdown.... [Oct 4 19:16:57] Executing last minute cleanups [Oct 4 19:16:57] == Destroying musiconhold processes [Oct 4 19:16:57] Asterisk cleanly ending (0). [Oct 4 19:16:57] DEBUG[28212]: asterisk.c:1189 quit_handler: Asterisk ending (0). [root@localhost ~]#