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