[Dec 2 19:40:30] <--- SIP read from 10.0.0.1:5060 ---> INVITE sip:1234@10.0.0.2 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 Max-Forwards: 69 Contact: To: "1234" From: ;tag=dc727c54 Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: eyeBeam release 1003s stamp 31159 Content-Length: 367 X-Custom-Duration: 7200000 v=0 o=- 6 2 IN IP4 10.2.0.1 s=CounterPath eyeBeam 1.5 c=IN IP4 10.2.0.1 t=0 0 m=audio 41226 RTP/AVP 18 101 a=alt:1 2 : ayB/6Vem b+VQaTgo 192.168.77.106 41226 a=alt:2 1 : CwITQhuK 5FwC68hr 10.2.0.1 41226 a=fmtp:18 annexb=no a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv a=x-rtp-session-id:DC80F86020F745A3949A424A4916ED45 <-------------> [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: INVITE sip:1234@10.0.0.2 SIP/2.0 (38) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Record-Route: (54) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 (61) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 (99) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Max-Forwards: 69 (16) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Contact: (45) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: To: "1234" (43) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: From: ;tag=dc727c54 (57) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: CSeq: 2 INVITE (14) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 11: Content-Type: application/sdp (29) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 12: User-Agent: eyeBeam release 1003s stamp 31159 (45) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 13: Content-Length: 367 (19) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 14: X-Custom-Duration: 7200000 (32) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 15: (0) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: v=0 (3) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: o=- 6 2 IN IP4 10.2.0.1 (29) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: s=CounterPath eyeBeam 1.5 (25) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: c=IN IP4 10.2.0.1 (23) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: t=0 0 (5) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: m=audio 41226 RTP/AVP 18 101 (28) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=alt:1 2 : ayB/6Vem b+VQaTgo 192.168.77.106 41226 (50) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=alt:2 1 : CwITQhuK 5FwC68hr 10.2.0.1 41226 (50) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=fmtp:18 annexb=no (19) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=fmtp:101 0-15 (15) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=sendrecv (10) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=x-rtp-session-id:DC80F86020F745A3949A424A4916ED45 (51) [Dec 2 19:40:30] --- (15 headers 13 lines) --- [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2553 do_setnat: Setting NAT on RTP to Off [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2558 do_setnat: Setting NAT on VRTP to Off [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2563 do_setnat: Setting NAT on UDPTL to Off [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4247 sip_alloc: Allocating new SIP dialog for 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. - INVITE (With RTP) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:14420 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 2 19:40:30] Sending to 10.0.0.1 : 5060 (no NAT) [Dec 2 19:40:30] Using INVITE request as basis request - 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. [Dec 2 19:40:30] Found peer 'ser' [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2553 do_setnat: Setting NAT on RTP to On [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2558 do_setnat: Setting NAT on VRTP to On [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2563 do_setnat: Setting NAT on UDPTL to On [Dec 2 19:40:30] Found RTP audio format 18 [Dec 2 19:40:30] Found RTP audio format 101 [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4821 process_sdp: Peer doesn't provide T.38 UDPTL [Dec 2 19:40:30] Peer audio RTP is at port 10.2.0.1:41226 [Dec 2 19:40:30] Got unsupported a:fmtp in SDP offer [Dec 2 19:40:30] Got unsupported a:fmtp in SDP offer [Dec 2 19:40:30] Found description format telephone-event for ID 101 [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:5051 process_sdp: T38 state changed to 0 on channel [Dec 2 19:40:30] Capabilities: us - 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Dec 2 19:40:30] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 2 19:40:30] Peer audio RTP is at port 10.2.0.1:41226 [Dec 2 19:40:30] Peer video RTP is at port 10.2.0.1:38662 [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:5128 process_sdp: We're settling with these formats: 0x100 (g729) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:13204 handle_request_invite: Checking SIP call limits for device [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Dec 2 19:40:30] Looking for 1234 in pre-process (domain 10.0.0.2) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:3754 sip_new: *** Our native formats are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:3755 sip_new: *** Joint capabilities are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:3756 sip_new: *** Our capabilities are 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:3757 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:3780 sip_new: This channel will not be able to handle video. [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:7843 build_route: build_route: Record-Route hop: [Dec 2 19:40:30] list_route: hop: [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:13277 handle_request_invite: SIP/mydomain.tld-08f727c0: New call is still down.... Trying... [Dec 2 19:40:30] <--- Transmitting (NAT) to 10.0.0.1:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0;received=10.0.0.1 Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 From: ;tag=dc727c54 To: "1234" Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 2 19:40:30] DEBUG[31118]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/mydomain.tld-08f727c0 [Dec 2 19:40:30] DEBUG[31101]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - mydomain.tld [Dec 2 19:40:30] DEBUG[31101]: chan_sip.c:15011 sip_devicestate: Checking device state for peer mydomain.tld [Dec 2 19:40:30] DEBUG[31101]: devicestate.c:287 do_state_change: Changing state for SIP/mydomain.tld - state 4 (Invalid) [Dec 2 19:40:30] DEBUG[31184]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Dec 2 19:40:30] -- Executing [1234@pre-process:1] SIPAddHeader("SIP/mydomain.tld-08f727c0", "X-Custom-Network: class4") in new stack [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:16773 sip_addheader: SIP Header added "X-Custom-Network: class4" as _SIPADDHEADER01 [Dec 2 19:40:30] DEBUG[31184]: pbx.c:1767 pbx_extension_helper: Launching 'SIPAddHeader' [Dec 2 19:40:30] -- Executing [1234@pre-process:2] SIPAddHeader("SIP/mydomain.tld-08f727c0", "X-Custom-Test3:") in new stack [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:16773 sip_addheader: SIP Header added "X-Custom-Test3:" as _SIPADDHEADER02 [Dec 2 19:40:30] DEBUG[31184]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' [Dec 2 19:40:30] -- Executing [1234@pre-process:3] Dial("SIP/mydomain.tld-08f727c0", "SIP/1234@ser") in new stack [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:15069 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4247 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2599 create_addr_from_peer: Our T38 capability (3856) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2553 do_setnat: Setting NAT on RTP to On [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2558 do_setnat: Setting NAT on VRTP to On [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2563 do_setnat: Setting NAT on UDPTL to On [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3754 sip_new: *** Our native formats are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3755 sip_new: *** Joint capabilities are 0x0 (nothing) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3756 sip_new: *** Our capabilities are 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3757 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3759 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:3780 sip_new: This channel will not be able to handle video. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-3. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER02. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-2. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-pre-process-1234-1. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable NODE_IP. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable TRANSFER_DB. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable TRANSFER_CONTEXT. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable EMER_NUMS. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable FAX_PROXY. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable PROXY. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable STRIP_CALLEE_CC. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable VM_GENERIC_NUM. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable VM_NUM. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable DEFAULT_LANGUAGE. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable GLOBAL_MAX_DURATION. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable GLOBAL_NOANS_TIMEOUT. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable MAX_LOOP. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable DEFAULT_COUNTRY_CODE. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3172 ast_channel_inherit_variables: Copying soft-transferable variable SERVICE_PROVIDER. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Dec 2 19:40:30] DEBUG[31184]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2804 sip_call: Outgoing Call for 1234 [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:2818 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6741 transmit_invite: Adding SIP Header "X-Custom-Test3" with content :: [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6741 transmit_invite: Adding SIP Header "X-Custom-Network" with content :class4: [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6104 add_sdp: ** Our capability: 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) Video flag: False [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6105 add_sdp: ** Our prefcodec: 0x100 (g729) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6120 add_sdp: This call needs video offers! [Dec 2 19:40:30] Video is at 10.0.0.2 port 12674 [Dec 2 19:40:30] Audio is at 10.0.0.2 port 19546 [Dec 2 19:40:30] Adding codec 0x100 (g729) to SDP [Dec 2 19:40:30] Adding codec 0x8 (alaw) to SDP [Dec 2 19:40:30] Adding codec 0x4 (ulaw) to SDP [Dec 2 19:40:30] Adding codec 0x2 (gsm) to SDP [Dec 2 19:40:30] Adding codec 0x400 (ilbc) to SDP [Dec 2 19:40:30] Adding codec 0x80000 (h263) to SDP [Dec 2 19:40:30] Adding codec 0x100000 (h263p) to SDP [Dec 2 19:40:30] Adding non-codec 0x1 (telephone-event) to SDP [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6236 add_sdp: -- Done with adding codecs to SDP [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:6281 add_sdp: Done building SDP. Settling with this capability: 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 0: INVITE sip:1234@10.0.0.1 SIP/2.0 (46) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport (65) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 3: To: (37) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 4: Contact: (39) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 6: CSeq: 102 INVITE (16) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 7: User-Agent: Asterisk (27) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 8: Max-Forwards: 70 (16) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 9: Remote-Party-ID: "2222" ;privacy=off;screen=no (89) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 10: Date: Sat, 02 Dec 2006 17:40:30 GMT (35) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 12: Supported: replaces (19) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 13: X-Custom-Test3: (24) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 14: X-Custom-Network: class4 (26) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 15: Content-Type: application/sdp (29) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 16: Content-Length: 487 (19) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4510 parse_request: Header 17: (0) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: v=0 (3) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: o=root 8990 8990 IN IP4 10.0.0.2 (38) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: s=session (9) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: c=IN IP4 10.0.0.2 (23) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: b=CT:384 (8) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: t=0 0 (5) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: m=audio 19546 RTP/AVP 18 8 0 3 97 101 (37) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=fmtp:18 annexb=no (19) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=fmtp:97 mode=30 (17) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=silenceSupp:off - - - - (25) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=ptime:20 (10) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=sendrecv (10) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: m=video 12674 RTP/AVP 34 103 (28) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:34 H263/90000 (22) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=rtpmap:103 h263-1998/90000 (28) [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:4542 parse_request: Line: a=sendrecv (10) [Dec 2 19:40:30] Reliably Transmitting (NAT) to 10.0.0.1:5060: INVITE sip:1234@10.0.0.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport From: "2222" ;tag=as7d90d1d4 To: Contact: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld CSeq: 102 INVITE User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "2222" ;privacy=off;screen=no Date: Sat, 02 Dec 2006 17:40:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-Custom-Test3: X-Custom-Network: class4 Content-Type: application/sdp Content-Length: 487 v=0 o=root 8990 8990 IN IP4 10.0.0.2 s=session c=IN IP4 10.0.0.2 b=CT:384 t=0 0 m=audio 19546 RTP/AVP 18 8 0 3 97 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 12674 RTP/AVP 34 103 a=rtpmap:34 H263/90000 a=rtpmap:103 h263-1998/90000 a=sendrecv --- [Dec 2 19:40:30] DEBUG[31184]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4 [Dec 2 19:40:30] -- Called 1234@ser [Dec 2 19:40:30] DEBUG[31185]: 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. [Dec 2 19:40:30] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld CSeq: 102 INVITE Server: OpenSER (1.1.0-notls (i386/linux)) Content-Length: 0 <-------------> [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 100 Trying (18) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: (37) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: OpenSER (1.1.0-notls (i386/linux)) (50) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: Content-Length: 0 (17) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: (0) [Dec 2 19:40:30] --- (8 headers 0 lines) --- [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2098 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #4 - INVITE (got response) [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' Request 102: Found [Dec 2 19:40:30] DEBUG[31118]: chan_sip.c:11510 handle_response_invite: SIP response 100 to standard invite [Dec 2 19:40:32] <--- SIP read from 10.0.0.1:5060 ---> CANCEL sip:1234@10.0.0.2 SIP/2.0 Max-Forwards: 10 Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 To: "1234" From: ;tag=dc727c54 Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 CANCEL Proxy-Authorization: Digest username="2222",realm="mydomain.tld",nonce="4571bbba2aba5ffaf9f89926f9405a99b696d5fc",uri="sip:1234@mydomain.tld",response="1cb2640b6f251acbcdb5833fb392820b",algorithm=MD5 User-Agent: eyeBeam release 1003s stamp 31159 Content-Length: 0 <-------------> [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: CANCEL sip:1234@10.0.0.2 SIP/2.0 (38) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Max-Forwards: 10 (16) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 (61) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 (99) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: To: "1234" (43) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: From: ;tag=dc727c54 (57) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 2 CANCEL (14) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Proxy-Authorization: Digest username="2222",realm="mydomain.tld",nonce="4571bbba2aba5ffaf9f89926f9405a99b696d5fc",uri="sip:1234@mydomain.tld",response="1cb2640b6f251acbcdb5833fb392820b",algorithm=MD5 (224) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: User-Agent: eyeBeam release 1003s stamp 31159 (45) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: Content-Length: 0 (17) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 11: (0) [Dec 2 19:40:32] --- (11 headers 0 lines) --- [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:14420 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Dec 2 19:40:32] Sending to 10.0.0.1 : 5060 (NAT) [Dec 2 19:40:32] <--- Reliably Transmitting (NAT) to 10.0.0.1:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0;received=10.0.0.1 Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 From: ;tag=dc727c54 To: "1234";tag=as1368de91 Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6 [Dec 2 19:40:32] <--- Transmitting (NAT) to 10.0.0.1:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0;received=10.0.0.1 Via: SIP/2.0/UDP 10.2.0.1:38012;branch=z9hG4bK-d87543-aa755b7cb9715753-1--d87543-;rport=38012 From: ;tag=dc727c54 To: "1234";tag=as1368de91 Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. CSeq: 2 CANCEL User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 2 19:40:32] DEBUG[31184]: rtp.c:1419 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Dec 2 19:40:32] DEBUG[31184]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/ser-08fa54e8' [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:3269 sip_hangup: Hangup call SIP/ser-08fa54e8, SIP callid 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld) [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:3277 sip_hangup: update_call_counter(1234) - decrement call limit counter on hangup [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Dec 2 19:40:32] Scheduling destruction of SIP dialog '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' in 32000 ms (Method: INVITE) [Dec 2 19:40:32] DEBUG[31184]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ser-08fa54e8 [Dec 2 19:40:32] DEBUG[31184]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Dec 2 19:40:32] DEBUG[31184]: pbx.c:2363 __ast_pbx_run: Spawn extension (pre-process,1234,3) exited non-zero on 'SIP/mydomain.tld-08f727c0' [Dec 2 19:40:32] == Spawn extension (pre-process, 1234, 3) exited non-zero on 'SIP/mydomain.tld-08f727c0' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2222' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2222' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1234' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'pre-process' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/mydomain.tld-08f727c0' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/ser-08fa54e8' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/1234@ser' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-02 19:40:30' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-02 19:40:32' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '0' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1165081230.0' [Dec 2 19:40:32] DEBUG[31184]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 2 19:40:32] DEBUG[31184]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/mydomain.tld-08f727c0' [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:3269 sip_hangup: Hangup call SIP/mydomain.tld-08f727c0, SIP callid 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.) [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:3277 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:2970 update_call_counter: Updating call counter for incoming call [Dec 2 19:40:32] DEBUG[31184]: chan_sip.c:3290 sip_hangup: Hanging up channel in state Ring (not UP) [Dec 2 19:40:32] DEBUG[31184]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/mydomain.tld-08f727c0 [Dec 2 19:40:32] <--- SIP read from 10.0.0.1:5060 ---> ACK sip:1234@10.0.0.2 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 From: ;tag=dc727c54 Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. To: "1234";tag=as1368de91 CSeq: 2 ACK User-Agent: OpenSER (1.1.0-notls (i386/linux)) Content-Length: 0 <-------------> [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: ACK sip:1234@10.0.0.2 SIP/2.0 (35) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.1;branch=z9hG4bK905b.ab975654.0 (61) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: ;tag=dc727c54 (57) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: Call-ID: 4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE. (69) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: To: "1234";tag=as1368de91 (58) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: CSeq: 2 ACK (11) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: User-Agent: OpenSER (1.1.0-notls (i386/linux)) (54) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: Content-Length: 0 (17) [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: (0) [Dec 2 19:40:32] --- (8 headers 0 lines) --- [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:14420 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6 [Dec 2 19:40:32] DEBUG[31118]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.' of Response 2: Match Not Found [Dec 2 19:40:32] Really destroying SIP dialog '4f0f2f57105f520dYjA4Y2Y4ZmYwNTEwNDQ5YzRmYzIzNzdhNzgxOWIyMmE.' Method: ACK [Dec 2 19:40:32] DEBUG[31101]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - ser [Dec 2 19:40:32] DEBUG[31101]: chan_sip.c:15011 sip_devicestate: Checking device state for peer ser [Dec 2 19:40:32] DEBUG[31101]: devicestate.c:287 do_state_change: Changing state for SIP/ser - state 1 (Not in use) [Dec 2 19:40:32] DEBUG[31101]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - mydomain.tld [Dec 2 19:40:32] DEBUG[31101]: chan_sip.c:15011 sip_devicestate: Checking device state for peer mydomain.tld [Dec 2 19:40:32] DEBUG[31186]: 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. [Dec 2 19:40:32] DEBUG[31101]: devicestate.c:287 do_state_change: Changing state for SIP/mydomain.tld - state 4 (Invalid) [Dec 2 19:40:32] DEBUG[31187]: 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. ovz*CLI> ovz*CLI> [Dec 2 19:40:36] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Date: Sat, 02 Dec 2006 17:40:30 GMT Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event Contact: Record-Route: Content-Disposition: session;handling=required Content-Type: application/sdp Content-Length: 346 v=0 o=CiscoSystemsSIP-GW-UserAgent 5082 9176 IN IP4 10.3.0.1 s=SIP Call c=IN IP4 10.3.0.1 t=0 0 m=audio 17440 RTP/AVP 18 101 c=IN IP4 10.3.0.1 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=silenceSupp:off - - - - m=video 0 RTP/AVP 34 c=IN IP4 10.3.0.1 <-------------> [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=D712A0C-19F8 (54) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Date: Sat, 02 Dec 2006 17:40:30 GMT (35) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 102 INVITE (16) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER (104) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: Allow-Events: telephone-event (29) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: Contact: (46) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 11: Record-Route: (56) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 12: Content-Disposition: session;handling=required (46) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 13: Content-Type: application/sdp (29) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 14: Content-Length: 346 (19) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 15: (0) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: v=0 (3) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 5082 9176 IN IP4 10.3.0.1 (61) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: s=SIP Call (10) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: c=IN IP4 10.3.0.1 (22) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: t=0 0 (5) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: m=audio 17440 RTP/AVP 18 101 (28) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: c=IN IP4 10.3.0.1 (22) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=fmtp:18 annexb=no (19) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=ptime:20 (10) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: a=silenceSupp:off - - - - (25) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: m=video 0 RTP/AVP 34 (20) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4542 parse_request: Line: c=IN IP4 10.3.0.1 (22) [Dec 2 19:40:36] --- (15 headers 15 lines) --- [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2107 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' Request 102: Found [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:11510 handle_response_invite: SIP response 183 to standard invite [Dec 2 19:40:36] Found RTP audio format 18 [Dec 2 19:40:36] Found RTP audio format 101 [Dec 2 19:40:36] Found RTP video format 34 [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4821 process_sdp: Peer doesn't provide T.38 UDPTL [Dec 2 19:40:36] Peer audio RTP is at port 10.3.0.1:17440 [Dec 2 19:40:36] Found description format G729 for ID 18 [Dec 2 19:40:36] Got unsupported a:fmtp in SDP offer [Dec 2 19:40:36] Found description format telephone-event for ID 101 [Dec 2 19:40:36] Got unsupported a:fmtp in SDP offer [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:5051 process_sdp: T38 state changed to 0 on channel [Dec 2 19:40:36] Capabilities: us - 0x18050e (gsm|ulaw|alaw|g729|ilbc|h263|h263p), peer - audio=0x80100 (g729|h263)/video=0x80000 (h263), combined - 0x80100 (g729|h263) [Dec 2 19:40:36] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 2 19:40:36] Peer audio RTP is at port 10.3.0.1:17440 [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:5128 process_sdp: We're settling with these formats: 0x80100 (g729|h263) [Dec 2 19:40:36] Reliably Transmitting (NAT) to 10.0.0.1:5060: CANCEL sip:1234@10.0.0.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport From: "2222" ;tag=as7d90d1d4 To: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld CSeq: 102 CANCEL User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "2222" ;privacy=off;screen=no Content-Length: 0 --- [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:1951 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #8 [Dec 2 19:40:36] Scheduling destruction of SIP dialog '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' in 32000 ms (Method: INVITE) [Dec 2 19:40:36] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 200 Canceling Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=b52076c0a0343c742375afff6878b100-5f52 Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld CSeq: 102 CANCEL Server: OpenSER (1.1.0-notls (i386/linux)) Content-Length: 0 <-------------> [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 200 Canceling (21) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=b52076c0a0343c742375afff6878b100-5f52 (79) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: CSeq: 102 CANCEL (16) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: OpenSER (1.1.0-notls (i386/linux)) (50) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: Content-Length: 0 (17) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: (0) [Dec 2 19:40:36] --- (8 headers 0 lines) --- [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2047 __sip_ack: Acked pending invite 102 [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2055 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #8 [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' of Request 102: Match Not Found [Dec 2 19:40:36] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Date: Sat, 02 Dec 2006 17:40:36 GMT Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=D712A0C-19F8 (54) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Date: Sat, 02 Dec 2006 17:40:36 GMT (35) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 102 INVITE (16) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Allow-Events: telephone-event (29) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: Content-Length: 0 (17) [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: (0) [Dec 2 19:40:36] --- (10 headers 0 lines) --- [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2065 __sip_ack: Stopping retransmission on '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' of Request 102: Match Not Found [Dec 2 19:40:36] DEBUG[31118]: chan_sip.c:2970 update_call_counter: Updating call counter for outgoing call [Dec 2 19:40:36] Transmitting (NAT) to 10.0.0.1:5060: ACK sip:1234@10.0.0.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Contact: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld CSeq: 102 ACK User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "2222" ;privacy=off;screen=no Content-Length: 0 --- [Dec 2 19:40:36] Really destroying SIP dialog '3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld' Method: INVITE [Dec 2 19:40:37] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Date: Sat, 02 Dec 2006 17:40:36 GMT Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=D712A0C-19F8 (54) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Date: Sat, 02 Dec 2006 17:40:36 GMT (35) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 102 INVITE (16) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Allow-Events: telephone-event (29) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: Content-Length: 0 (17) [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: (0) [Dec 2 19:40:37] --- (10 headers 0 lines) --- [Dec 2 19:40:37] DEBUG[31118]: chan_sip.c:14598 sipsock_read: Invalid SIP message - rejected , no callid, len 440 [Dec 2 19:40:39] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Date: Sat, 02 Dec 2006 17:40:36 GMT Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=D712A0C-19F8 (54) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Date: Sat, 02 Dec 2006 17:40:36 GMT (35) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 102 INVITE (16) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Allow-Events: telephone-event (29) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: Content-Length: 0 (17) [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: (0) [Dec 2 19:40:39] --- (10 headers 0 lines) --- [Dec 2 19:40:39] DEBUG[31118]: chan_sip.c:14598 sipsock_read: Invalid SIP message - rejected , no callid, len 440 [Dec 2 19:40:43] <--- SIP read from 10.0.0.1:5060 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 From: "2222" ;tag=as7d90d1d4 To: ;tag=D712A0C-19F8 Date: Sat, 02 Dec 2006 17:40:36 GMT Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK0e824235;rport=5060 (70) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 2: From: "2222" ;tag=as7d90d1d4 (71) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 3: To: ;tag=D712A0C-19F8 (54) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 4: Date: Sat, 02 Dec 2006 17:40:36 GMT (35) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 5: Call-ID: 3f4b02210d23d1ce09136d8804f75c9d@mydomain.tld (64) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 7: CSeq: 102 INVITE (16) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 8: Allow-Events: telephone-event (29) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 9: Content-Length: 0 (17) [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:4510 parse_request: Header 10: (0) [Dec 2 19:40:43] --- (10 headers 0 lines) --- [Dec 2 19:40:43] DEBUG[31118]: chan_sip.c:14598 sipsock_read: Invalid SIP message - rejected , no callid, len 440 ovz*CLI>