--- Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6433 <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK519dab0e;rport=5060 From: ;tag=as1965a279 To: Call-ID: 3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1 CSeq: 102 REGISTER Contact: user-agent: Asterisk PBX expires: 120 event: registration Allow: REFER, INFO, BYE, CANCEL, INVITE Content-Length: 0 Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 200 OK (14) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK519dab0e;rport=5060 (70) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: ;tag=as1965a279 (48) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: (31) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1 (51) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 REGISTER (18) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: (29) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: user-agent: Asterisk PBX (24) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: expires: 120 (12) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: event: registration (19) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Allow: REFER, INFO, BYE, CANCEL, INVITE (39) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: Content-Length: 0 (17) Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 12: (0) --- (12 headers 0 lines) --- Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1 Their Tag Our tag: as1965a279 Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6433 Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1' of Request 102: Match Found Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:9941 handle_response_register: Registration successful Apr 9 22:05:34 DEBUG[9157]: chan_sip.c:9943 handle_response_register: Cancelling timeout 6432 Scheduling destruction of call '3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1' in 32000 ms Apr 9 22:05:34 NOTICE[9157]: chan_sip.c:9993 handle_response_register: Outbound Registration: Expiry for XXX.XXX.XXX.154 is 120 sec (Scheduling reregistration in 105 s) asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: INVITE sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK2185363103192047158 From: "1111";tag=c0a80101-4a7aa46 To: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 1 INVITE Max-Forwards: 70 Supported: timer, replaces Session-Expires: 1800 Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO Contact: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 Content-Type: application/sdp Content-Length: 145 v=0 o=1111 78096967 78096967 IN IP4 192.168.0.31 s=- c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=sendrecv Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: INVITE sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 (43) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK2185363103192047158 (68) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "1111";tag=c0a80101-4a7aa46 (74) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: (45) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 1 INVITE (14) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Max-Forwards: 70 (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Supported: timer, replaces (26) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Session-Expires: 1800 (21) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO (86) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Contact: (48) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 (55) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 12: Content-Type: application/sdp (29) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 13: Content-Length: 145 (19) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 14: (0) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: o=1111 78096967 78096967 IN IP4 192.168.0.31 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: s=- (3) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: c=IN IP4 192.168.0.31 (21) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: m=audio 41000 RTP/AVP 4 (23) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=sendrecv (10) --- (14 headers 8 lines) --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1 Their Tag Our tag: as1965a279 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3196 sip_alloc: Allocating new SIP dialog for 61324107-c0a80101-0-1d@192.168.0.31 - INVITE (With RTP) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received INVITE (5) - Command in SIP INVITE Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1015 parse_sip_options: Begin: parsing SIP "Supported: timer, replaces" Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1027 parse_sip_options: Found SIP option: -timer- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1033 parse_sip_options: Matched SIP option: timer Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1027 parse_sip_options: Found SIP option: -replaces- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1033 parse_sip_options: Matched SIP option: replaces Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1044 parse_sip_options: * SIP extension value: 5 for call 61324107-c0a80101-0-1d@192.168.0.31 Using INVITE request as basis request - 61324107-c0a80101-0-1d@192.168.0.31 Sending to 192.168.0.31 : 5060 (non-NAT) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:7296 check_user_full: Setting NAT on RTP to 0 Reliably Transmitting (no NAT) to 192.168.0.31:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK2185363103192047158;received=192.168.0.31 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as378ae32a Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="68839a67" Content-Length: 0 --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6436 Scheduling destruction of call '61324107-c0a80101-0-1d@192.168.0.31' in 15000 ms Found user '1111' Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3196 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: NOTIFY sip:1111@192.168.0.31:5060;user=phone SIP/2.0 (52) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK2e63b8b5 (59) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "asterisk" ;tag=as55623e01 (61) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: (43) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Contact: (38) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: Call-ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 (56) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: CSeq: 102 NOTIFY (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: User-Agent: Asterisk PBX (24) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Max-Forwards: 70 (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Event: message-summary (22) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Content-Type: application/simple-message-summary (48) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: Content-Length: 94 (18) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 12: (0) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: Messages-Waiting: no (20) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: Message-Account: sip:asterisk@XXX.XXX.XXX.242 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: Voice-Message: 0/0 (0/0) (24) 12 headers, 3 lines Reliably Transmitting (no NAT) to 192.168.0.31:5060: NOTIFY sip:1111@192.168.0.31:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK2e63b8b5 From: "asterisk" ;tag=as55623e01 To: Contact: Call-ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:asterisk@XXX.XXX.XXX.242 Voice-Message: 0/0 (0/0) --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6438 Scheduling destruction of call '7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242' in 15000 ms asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: ACK sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK2185363103192047158 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as378ae32a Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 1 ACK Max-Forwards: 70 User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 Content-Length: 0 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: ACK sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 (40) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK2185363103192047158 (68) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "1111";tag=c0a80101-4a7aa46 (74) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=as378ae32a (60) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 1 ACK (11) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Max-Forwards: 70 (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 (55) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Content-Length: 0 (17) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: (0) --- (9 headers 0 lines) --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 Their Tag Our tag: as55623e01 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as378ae32a Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received ACK (6) - Command in SIP ACK Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6436 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '61324107-c0a80101-0-1d@192.168.0.31' of Response 1: Match Found asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: INVITE sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK1963248081981436936 From: "1111";tag=c0a80101-4a7aa46 To: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 2 INVITE Max-Forwards: 70 Supported: timer, replaces Session-Expires: 1800 Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242:5060", response="8a46feffd9e35f3d22dc3a09c5898390", algorithm=MD5 Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO Contact: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 Content-Type: application/sdp Content-Length: 145 v=0 o=1111 78096967 78096967 IN IP4 192.168.0.31 s=- c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=sendrecv Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: INVITE sip:7676@XXX.XXX.XXX.242:5060 SIP/2.0 (43) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK1963248081981436936 (68) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "1111";tag=c0a80101-4a7aa46 (74) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: (45) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 2 INVITE (14) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Max-Forwards: 70 (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Supported: timer, replaces (26) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Session-Expires: 1800 (21) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242:5060", response="8a46feffd9e35f3d22dc3a09c5898390", algorithm=MD5 (175) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO (86) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: Contact: (48) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 12: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 (55) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 13: Content-Type: application/sdp (29) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 14: Content-Length: 145 (19) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 15: (0) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: o=1111 78096967 78096967 IN IP4 192.168.0.31 (44) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: s=- (3) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: c=IN IP4 192.168.0.31 (21) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: m=audio 41000 RTP/AVP 4 (23) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=sendrecv (10) --- (15 headers 8 lines) --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 Their Tag Our tag: as55623e01 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as378ae32a Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 61324107-c0a80101-0-1d@192.168.0.31 Sending to 192.168.0.31 : 5060 (non-NAT) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:7296 check_user_full: Setting NAT on RTP to 0 Found user '1111' Found RTP audio format 4 Peer audio RTP is at port 192.168.0.31:41000 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3689 process_sdp: Peer audio RTP is at port 192.168.0.31:41000 Found description format G723 Capabilities: us - 0x8010f (g723|gsm|ulaw|alaw|g729|h263), peer - audio=0x1 (g723)/video=0x0 (nothing), combined - 0x1 (g723) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:10674 handle_request_invite: Checking SIP call limits for device 1111 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:2233 update_call_counter: Updating call counter for incoming call Looking for 7676 in from-sip-external (domain XXX.XXX.XXX.242) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:6272 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 192.168.0.31:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK1963248081981436936;received=192.168.0.31 From: "1111";tag=c0a80101-4a7aa46 To: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Apr 9 22:05:37 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:05:37 DEBUG[9151]: devicestate.c:187 do_state_change: Changing state for SIP/1111 - state 2 (In use) Apr 9 22:05:37 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:05:37 DEBUG[14006]: pbx.c:1697 pbx_extension_helper: Launching 'Wait' -- Executing Wait("SIP/1111-089a5d58", "1") in new stack <-- SIP read from 192.168.0.31:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK2e63b8b5 From: "asterisk";tag=as55623e01 To: ;tag=c0a80101-4a7aa65 Call-ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 CSeq: 102 NOTIFY Content-Length: 0 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 200 OK (14) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK2e63b8b5 (59) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "asterisk";tag=as55623e01 (60) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=c0a80101-4a7aa65 (64) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 (56) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 NOTIFY (16) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Content-Length: 0 (17) Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: (0) --- (7 headers 0 lines) --- Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242 Their Tag Our tag: as55623e01 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6438 Apr 9 22:05:37 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242' of Request 102: Match Found Destroying call '7f37a273351b0400783db07a5bef1454@XXX.XXX.XXX.242' Apr 9 22:05:37 DEBUG[14007]: app_queue.c:500 changethread: Device 'SIP/1111' changed to state '2' (In use) but we don't care because they're not a member of any queue. Apr 9 22:05:38 DEBUG[14006]: pbx.c:1697 pbx_extension_helper: Launching 'Playback' -- Executing Playback("SIP/1111-089a5d58", "connected") in new stack Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:2575 sip_answer: sip_answer(SIP/1111-089a5d58) We're at XXX.XXX.XXX.242 port 64802 Adding codec 0x1 (g723) to SDP Reliably Transmitting (no NAT) to 192.168.0.31:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK1963248081981436936;received=192.168.0.31 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as1c3f84a4 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 162 v=0 o=root 9147 9147 IN IP4 XXX.XXX.XXX.242 s=session c=IN IP4 XXX.XXX.XXX.242 t=0 0 m=audio 64802 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - --- Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6440 Apr 9 22:05:38 DEBUG[14006]: channel.c:2414 set_format: Set channel SIP/1111-089a5d58 to write format gsm -- Playing 'connected' (language 'fr') Apr 9 22:05:38 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:05:38 DEBUG[9151]: devicestate.c:187 do_state_change: Changing state for SIP/1111 - state 2 (In use) Apr 9 22:05:38 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:05:38 DEBUG[14008]: app_queue.c:500 changethread: Device 'SIP/1111' changed to state '2' (In use) but we don't care because they're not a member of any queue. Apr 9 22:05:38 DEBUG[14006]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to g723 asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: ACK sip:7676@XXX.XXX.XXX.242 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK6859147581970425821 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as1c3f84a4 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 2 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242", response="185b46c4d28eca3d6831947fe6e26de1", algorithm=MD5 User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 Content-Length: 0 Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: ACK sip:7676@XXX.XXX.XXX.242 SIP/2.0 (35) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK6859147581970425821 (68) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "1111";tag=c0a80101-4a7aa46 (74) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=as1c3f84a4 (60) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 2 ACK (11) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Max-Forwards: 70 (16) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242", response="185b46c4d28eca3d6831947fe6e26de1", algorithm=MD5 (170) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 (55) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Content-Length: 0 (17) Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: (0) --- (10 headers 0 lines) --- Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as1c3f84a4 Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received ACK (6) - Command in SIP ACK Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6440 Apr 9 22:05:38 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '61324107-c0a80101-0-1d@192.168.0.31' of Response 2: Match Found Apr 9 22:05:38 DEBUG[14006]: channel.c:2414 set_format: Set channel SIP/1111-089a5d58 to write format g723 Apr 9 22:05:38 DEBUG[14006]: pbx.c:1697 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/1111-089a5d58", "SIP/33XXXXXXXXX@XXX.XXX.XXX.154") in new stack Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3196 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-from-sip-external-7676-3. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-from-sip-external-7676-2. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-from-sip-external-7676-1. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPCALLID. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Apr 9 22:05:38 DEBUG[14006]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPURI. Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:2088 sip_call: Outgoing Call for 33XXXXXXXXX Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:2233 update_call_counter: Updating call counter for outgoing call We're at XXX.XXX.XXX.242 port 33810 Adding codec 0x1 (g723) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 0: INVITE sip:33XXXXXXXXX@XXX.XXX.XXX.154 SIP/2.0 (44) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport (65) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 3: To: (35) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 4: Contact: (34) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 5: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 6: CSeq: 102 INVITE (16) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 7: User-Agent: Asterisk PBX (24) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 8: Max-Forwards: 70 (16) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 9: Date: Mon, 09 Apr 2007 20:05:38 GMT (35) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 11: Content-Type: application/sdp (29) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 12: Content-Length: 336 (19) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 13: (0) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: o=root 9147 9147 IN IP4 XXX.XXX.XXX.242 (38) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: s=session (9) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: c=IN IP4 XXX.XXX.XXX.242 (23) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: m=audio 33810 RTP/AVP 4 18 3 0 8 101 (36) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:18 G729/8000 (21) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=fmtp:18 annexb=no (19) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:3 GSM/8000 (19) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=fmtp:101 0-16 (15) Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 15 lines Reliably Transmitting (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:33XXXXXXXXX@XXX.XXX.XXX.154 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport From: "logan home" ;tag=as25f1c328 To: Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 09 Apr 2007 20:05:38 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 336 v=0 o=root 9147 9147 IN IP4 XXX.XXX.XXX.242 s=session c=IN IP4 XXX.XXX.XXX.242 t=0 0 m=audio 33810 RTP/AVP 4 18 3 0 8 101 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Apr 9 22:05:38 DEBUG[14006]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6441 -- Called 33XXXXXXXXX@XXX.XXX.XXX.154 asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 102 INVITE Contact: user-agent: Asterisk PBX date: Mon, 09 Apr 2007 20:05:38 GMT Content-Length: 0 Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 100 Trying (18) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 (70) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 INVITE (16) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: (34) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: user-agent: Asterisk PBX (24) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: date: Mon, 09 Apr 2007 20:05:38 GMT (35) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Content-Length: 0 (17) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: (0) --- (10 headers 0 lines) --- Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag Our tag: as25f1c328 Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:1464 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #6441 - INVITE (got response) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:1473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' Request 102: Found Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:9725 handle_response_invite: SIP response 100 to standard invite asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 102 INVITE Contact: user-agent: Asterisk PBX date: Mon, 09 Apr 2007 20:05:38 GMT Content-Type: application/sdp Content-Length: 234 v=0 o=Clarent 212134 212135 IN IP4 XXX.XXX.XXX.100 s=Clarent C5CM c=IN IP4 XXX.XXX.XXX.100 t=0 0 m=audio 5142 RTP/AVP 4 0 8 18 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=SendRecv Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 (70) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 INVITE (16) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: (34) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: user-agent: Asterisk PBX (24) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: date: Mon, 09 Apr 2007 20:05:38 GMT (35) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Content-Type: application/sdp (29) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Content-Length: 234 (21) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: (0) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: o=Clarent 212134 212135 IN IP4 XXX.XXX.XXX.100 (46) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: s=Clarent C5CM (14) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: c=IN IP4 XXX.XXX.XXX.100 (24) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: m=audio 5142 RTP/AVP 4 0 8 18 (29) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:18 G729/8000 (21) Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=SendRecv (10) --- (11 headers 11 lines) --- Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:1473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' Request 102: Found Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:9725 handle_response_invite: SIP response 183 to standard invite Found RTP audio format 4 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Peer audio RTP is at port XXX.XXX.XXX.100:5142 Apr 9 22:05:39 DEBUG[9157]: chan_sip.c:3689 process_sdp: Peer audio RTP is at port XXX.XXX.XXX.100:5142 Found description format G723 Found description format PCMU Found description format PCMA Found description format G729 Capabilities: us - 0x8010f (g723|gsm|ulaw|alaw|g729|h263), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x10d (g723|ulaw|alaw|g729) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) -- SIP/XXX.XXX.XXX.154-089a8978 is making progress passing it to SIP/1111-089a5d58 Apr 9 22:05:39 DEBUG[14006]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to g723 Apr 9 22:05:45 DEBUG[14006]: rtp.c:411 ast_rtcp_read: Got RTCP report of 116 bytes asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 102 INVITE Contact: "Verso C5CM" user-agent: Asterisk PBX date: Mon, 09 Apr 2007 20:05:38 GMT Content-Type: application/sdp Content-Length: 224 v=0 o=Clarent 1 0 IN IP4 XXX.XXX.XXX.100 s=Clarent C5CM c=IN IP4 XXX.XXX.XXX.100 t=0 0 m=audio 5142 RTP/AVP 4 0 8 18 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=SendRecv Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 200 OK (14) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK3cc29820;rport=5060 (70) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 INVITE (16) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: "Verso C5CM" (46) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: user-agent: Asterisk PBX (24) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: date: Mon, 09 Apr 2007 20:05:38 GMT (35) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Content-Type: application/sdp (29) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Content-Length: 224 (21) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: (0) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: o=Clarent 1 0 IN IP4 XXX.XXX.XXX.100 (36) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: s=Clarent C5CM (14) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: c=IN IP4 XXX.XXX.XXX.100 (24) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: m=audio 5142 RTP/AVP 4 0 8 18 (29) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:18 G729/8000 (21) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=SendRecv (10) --- (11 headers 11 lines) --- Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1397 __sip_ack: Acked pending invite 102 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' of Request 102: Match Found Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:9725 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 4 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Peer audio RTP is at port XXX.XXX.XXX.100:5142 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3689 process_sdp: Peer audio RTP is at port XXX.XXX.XXX.100:5142 Found description format G723 Found description format PCMU Found description format PCMA Found description format G729 Capabilities: us - 0x8010f (g723|gsm|ulaw|alaw|g729|h263), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x10d (g723|ulaw|alaw|g729) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:6272 build_route: build_route: Contact hop: "Verso C5CM" list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to XXX.XXX.XXX.154, port 5060 Transmitting (no NAT) to XXX.XXX.XXX.154:5060: ACK sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK391a8848;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- SIP/XXX.XXX.XXX.154-089a8978 answered SIP/1111-089a5d58 -- Attempting native bridge of SIP/1111-089a5d58 and SIP/XXX.XXX.XXX.154-089a8978 Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:13132 sip_set_rtp_peer: Sending reinvite on SIP '61324107-c0a80101-0-1d@192.168.0.31' - It's audio soon redirected to IP XXX.XXX.XXX.100 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.31, port 5060 We're at XXX.XXX.XXX.242 port 64802 Adding codec 0x1 (g723) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 0: INVITE sip:1111@192.168.0.31:5060 SIP/2.0 (41) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 (59) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 2: From: ;tag=as1c3f84a4 (62) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 3: To: "1111";tag=c0a80101-4a7aa46 (72) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 4: Contact: (34) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 5: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 6: CSeq: 102 INVITE (16) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 7: User-Agent: Asterisk PBX (24) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 8: Max-Forwards: 70 (16) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (43) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 11: Content-Type: application/sdp (29) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 12: Content-Length: 258 (19) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 13: (0) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: o=root 9147 9148 IN IP4 XXX.XXX.XXX.100 (39) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: s=session (9) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: c=IN IP4 XXX.XXX.XXX.100 (24) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: m=audio 5142 RTP/AVP 4 18 0 8 (29) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:18 G729/8000 (21) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=fmtp:18 annexb=no (19) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 12 lines Reliably Transmitting (no NAT) to 192.168.0.31:5060: INVITE sip:1111@192.168.0.31:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 From: ;tag=as1c3f84a4 To: "1111";tag=c0a80101-4a7aa46 Contact: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 258 v=0 o=root 9147 9148 IN IP4 XXX.XXX.XXX.100 s=session c=IN IP4 XXX.XXX.XXX.100 t=0 0 m=audio 5142 RTP/AVP 4 18 0 8 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - --- Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6442 Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:13132 sip_set_rtp_peer: Sending reinvite on SIP '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' - It's audio soon redirected to IP 192.168.0.31 set_destination: Parsing for address/port to send to set_destination: set destination to XXX.XXX.XXX.154, port 5060 We're at XXX.XXX.XXX.242 port 33810 Adding codec 0x1 (g723) to SDP Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 0: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 (37) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport (65) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 4: Contact: (34) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 5: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 6: CSeq: 103 INVITE (16) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 7: User-Agent: Asterisk PBX (24) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 8: Max-Forwards: 70 (16) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (43) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 11: Content-Type: application/sdp (29) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 12: Content-Length: 158 (19) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3447 parse_request: Header 13: (0) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: o=root 9147 9148 IN IP4 192.168.0.31 (36) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: s=session (9) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: c=IN IP4 192.168.0.31 (21) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: m=audio 41000 RTP/AVP 4 (23) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:3479 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 8 lines Reliably Transmitting (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - --- Apr 9 22:05:49 DEBUG[14006]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6443 Apr 9 22:05:49 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer XXX.XXX.XXX.154 Apr 9 22:05:49 DEBUG[9151]: devicestate.c:187 do_state_change: Changing state for SIP/XXX.XXX.XXX.154 - state 2 (In use) Apr 9 22:05:49 DEBUG[14011]: app_queue.c:500 changethread: Device 'SIP/XXX.XXX.XXX.154' changed to state '2' (In use) but we don't care because they're not a member of any queue. asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 From: "7676";tag=as1c3f84a4 To: ;tag=c0a80101-4a7aa46 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 102 INVITE Content-Length: 0 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 100 Trying (18) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 (59) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "7676";tag=as1c3f84a4 (68) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=c0a80101-4a7aa46 (66) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 INVITE (16) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Content-Length: 0 (17) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: (0) --- (7 headers 0 lines) --- Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as1c3f84a4 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1464 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #6442 - INVITE (got response) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '61324107-c0a80101-0-1d@192.168.0.31' Request 102: Found Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:9723 handle_response_invite: SIP response 100 to RE-invite on outgoing call 61324107-c0a80101-0-1d@192.168.0.31 asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 From: "7676";tag=as1c3f84a4 To: ;tag=c0a80101-4a7aa46 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 102 INVITE Contact: Content-Type: application/sdp Content-Length: 145 v=0 o=1111 78096967 78096967 IN IP4 192.168.0.31 s=- c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=sendrecv Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 200 OK (14) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK77c43311 (59) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "7676";tag=as1c3f84a4 (68) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=c0a80101-4a7aa46 (66) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 102 INVITE (16) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: (48) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Content-Type: application/sdp (29) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Content-Length: 145 (19) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: (0) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: v=0 (3) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: o=1111 78096967 78096967 IN IP4 192.168.0.31 (44) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: s=- (3) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: c=IN IP4 192.168.0.31 (21) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: t=0 0 (5) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: m=audio 41000 RTP/AVP 4 (23) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=rtpmap:4 G723/8000 (20) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3479 parse_request: Line: a=sendrecv (10) --- (9 headers 8 lines) --- Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as1c3f84a4 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1397 __sip_ack: Acked pending invite 102 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '61324107-c0a80101-0-1d@192.168.0.31' of Request 102: Match Found Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:9723 handle_response_invite: SIP response 200 to RE-invite on outgoing call 61324107-c0a80101-0-1d@192.168.0.31 Found RTP audio format 4 Peer audio RTP is at port 192.168.0.31:41000 Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:3689 process_sdp: Peer audio RTP is at port 192.168.0.31:41000 Found description format G723 Capabilities: us - 0x8010f (g723|gsm|ulaw|alaw|g729|h263), peer - audio=0x1 (g723)/video=0x0 (nothing), combined - 0x1 (g723) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Apr 9 22:05:49 DEBUG[9157]: chan_sip.c:6272 build_route: build_route: Contact hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.31, port 5060 Transmitting (no NAT) to 192.168.0.31:5060: ACK sip:1111@192.168.0.31:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK6b6d0ee8 From: ;tag=as1c3f84a4 To: "1111";tag=c0a80101-4a7aa46 Contact: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Apr 9 22:05:50 DEBUG[9157]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #6443 (1) INVITE - 5 Apr 9 22:05:50 DEBUG[9157]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #6443)) Retransmitting #1 (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - ---erisk04*CLI> Apr 9 22:05:51 DEBUG[9157]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #6443 (2) INVITE - 5 Apr 9 22:05:51 DEBUG[9157]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #6443)) Retransmitting #2 (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - ---erisk04*CLI> Apr 9 22:05:53 DEBUG[9157]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #6443 (3) INVITE - 5 Apr 9 22:05:53 DEBUG[9157]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #6443)) Retransmitting #3 (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - ---erisk04*CLI> Apr 9 22:05:57 DEBUG[9157]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #6443 (4) INVITE - 5 Apr 9 22:05:57 DEBUG[9157]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 8000 ms (t1 500 ms (Retrans id #6443)) Retransmitting #4 (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - ---erisk04*CLI> Apr 9 22:06:01 WARNING[9165]: chan_oh323.c:4250 oh323_gk_check: Failed to register with gatekeeper 'XXX.XXX.XXX.242'. -- Retrying gatekeeper registration. Apr 9 22:06:05 DEBUG[9157]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #6443 (5) INVITE - 5 Apr 9 22:06:05 DEBUG[9157]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 16000 ms (t1 500 ms (Retrans id #6443)) Retransmitting #5 (no NAT) to XXX.XXX.XXX.154:5060: INVITE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 158 v=0 o=root 9147 9148 IN IP4 192.168.0.31 s=session c=IN IP4 192.168.0.31 t=0 0 m=audio 41000 RTP/AVP 4 a=rtpmap:4 G723/8000 a=silenceSupp:off - - - - asterisk04*CLI> --- Apr 9 22:06:06 DEBUG[9157]: chan_sip.c:1341 __sip_autodestruct: Auto destroying call '3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1' Destroying call '3d23b84f4075893e43f5e7503dfe0f7d@127.0.0.1' asterisk04*CLI> <-- SIP read from 192.168.0.31:5060: BYE sip:7676@XXX.XXX.XXX.242 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK6419703547536481491 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as1c3f84a4 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 3 BYE Max-Forwards: 70 Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242", response="d5d6f1f0950b2e38e9f5102468ae4825", algorithm=MD5 User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 Content-Length: 0 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: BYE sip:7676@XXX.XXX.XXX.242 SIP/2.0 (35) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK6419703547536481491 (68) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "1111";tag=c0a80101-4a7aa46 (74) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=as1c3f84a4 (60) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 (44) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 3 BYE (11) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Max-Forwards: 70 (16) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Proxy-Authorization: Digest username="1111", realm="asterisk", nonce="68839a67", uri="sip:7676@XXX.XXX.XXX.242", response="d5d6f1f0950b2e38e9f5102468ae4825", algorithm=MD5 (170) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: User-Agent: THOMSON ST2030 hw5 fw1.50 00-14-7F-00-7D-33 (55) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Content-Length: 0 (17) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: (0) --- (10 headers 0 lines) --- Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3244 find_call: = No match Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 61324107-c0a80101-0-1d@192.168.0.31 Their Tag c0a80101-4a7aa46 Our tag: as1c3f84a4 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.0.31 : 5060 (non-NAT) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:10963 handle_request_bye: Received bye, issuing owner hangup Transmitting (no NAT) to 192.168.0.31:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.31:5060;branch=z9hG4bK6419703547536481491;received=192.168.0.31 From: "1111";tag=c0a80101-4a7aa46 To: ;tag=as1c3f84a4 Call-ID: 61324107-c0a80101-0-1d@192.168.0.31 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- Apr 9 22:06:09 DEBUG[14006]: rtp.c:1722 ast_rtp_bridge: Oooh, got a hangup Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:13138 sip_set_rtp_peer: Deferring reinvite on SIP '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' - It's audio will be redirected to IP XXX.XXX.XXX.242 Apr 9 22:06:09 DEBUG[14006]: channel.c:3613 ast_channel_bridge: Returning from native bridge, channels: SIP/1111-089a5d58, SIP/XXX.XXX.XXX.154-089a8978 Apr 9 22:06:09 DEBUG[14006]: channel.c:1371 ast_hangup: Hanging up channel 'SIP/XXX.XXX.XXX.154-089a8978' Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2445 sip_hangup: Hangup call SIP/XXX.XXX.XXX.154-089a8978, SIP callid 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242) Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2453 sip_hangup: update_call_counter(33XXXXXXXXX) - decrement call limit counter Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2233 update_call_counter: Updating call counter for outgoing call Scheduling destruction of call '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' in 32000 ms set_destination: Parsing for address/port to send to set_destination: set destination to XXX.XXX.XXX.154, port 5060 Reliably Transmitting (no NAT) to XXX.XXX.XXX.154:5060: BYE sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK0c425f6b;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6445 Apr 9 22:06:09 DEBUG[14006]: app_dial.c:1644 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Apr 9 22:06:09 DEBUG[14006]: pbx.c:2336 __ast_pbx_run: Spawn extension (from-sip-external,7676,3) exited non-zero on 'SIP/1111-089a5d58' == Spawn extension (from-sip-external, 7676, 3) exited non-zero on 'SIP/1111-089a5d58' Apr 9 22:06:09 DEBUG[14006]: pbx.c:1697 pbx_extension_helper: Launching 'Hangup' -- Executing Hangup("SIP/1111-089a5d58", "") in new stack Apr 9 22:06:09 DEBUG[14006]: pbx.c:2474 __ast_pbx_run: Spawn extension (from-sip-external,h,1) exited non-zero on 'SIP/1111-089a5d58' == Spawn extension (from-sip-external, h, 1) exited non-zero on 'SIP/1111-089a5d58' Apr 9 22:06:09 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer XXX.XXX.XXX.154 Apr 9 22:06:09 DEBUG[9151]: devicestate.c:187 do_state_change: Changing state for SIP/XXX.XXX.XXX.154 - state 1 (Not in use) Apr 9 22:06:09 DEBUG[14006]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Apr 9 22:06:09 DEBUG[14006]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-09 22:05:37','\"logan home\" <1111>','1111','7676','from-sip-external', 'SIP/1111-089a5d58','SIP/XXX.XXX.XXX.154-089a8978','Hangup','',32,31,'ANSWERED',3,'','1176149137.12') Apr 9 22:06:09 DEBUG[14006]: channel.c:1371 ast_hangup: Hanging up channel 'SIP/1111-089a5d58' Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2445 sip_hangup: Hangup call SIP/1111-089a5d58, SIP callid 61324107-c0a80101-0-1d@192.168.0.31) Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2453 sip_hangup: update_call_counter(1111) - decrement call limit counter Apr 9 22:06:09 DEBUG[14006]: chan_sip.c:2233 update_call_counter: Updating call counter for outgoing call Apr 9 22:06:09 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:06:09 DEBUG[9151]: devicestate.c:187 do_state_change: Changing state for SIP/1111 - state 1 (Not in use) Apr 9 22:06:09 DEBUG[9151]: chan_sip.c:11871 sip_devicestate: Checking device state for peer 1111 Apr 9 22:06:09 DEBUG[14014]: app_queue.c:500 changethread: Device 'SIP/XXX.XXX.XXX.154' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Apr 9 22:06:09 DEBUG[14015]: app_queue.c:500 changethread: Device 'SIP/1111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK0c425f6b;rport=5060 From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 104 BYE user-agent: Asterisk PBX Content-Length: 0 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 200 OK (14) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK0c425f6b;rport=5060 (70) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 104 BYE (13) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: user-agent: Asterisk PBX (24) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: Content-Length: 0 (17) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: (0) --- (8 headers 0 lines) --- Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6445 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' of Request 104: Match Found Destroying call '61324107-c0a80101-0-1d@192.168.0.31' asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.154:5060: SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport=5060 From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 INVITE Contact: user-agent: Asterisk PBX x-asterisk-info: SIP re-invite (RTP bridge) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: SIP/2.0 487 Request Cancelled (30) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK170ffe47;rport=5060 (70) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "logan home" ;tag=as25f1c328 (59) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: ;tag=GR52RWG346-34 (53) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 (56) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: CSeq: 103 INVITE (16) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: Contact: (34) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: user-agent: Asterisk PBX (24) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: x-asterisk-info: SIP re-invite (RTP bridge) (43) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Content-Length: 0 (17) Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: (0) --- (11 headers 0 lines) --- Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:3244 find_call: = Found Their Call ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 Their Tag GR52RWG346-34 Our tag: as25f1c328 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:1397 __sip_ack: Acked pending invite 103 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6443 Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' of Request 103: Match Found Apr 9 22:06:09 DEBUG[9157]: chan_sip.c:9725 handle_response_invite: SIP response 487 to standard invite set_destination: Parsing for address/port to send to set_destination: set destination to XXX.XXX.XXX.154, port 5060 Transmitting (no NAT) to XXX.XXX.XXX.154:5060: ACK sip:XXX.XXX.XXX.154:5060 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.242:5060;branch=z9hG4bK0c425f6b;rport From: "logan home" ;tag=as25f1c328 To: ;tag=GR52RWG346-34 Contact: Call-ID: 757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Destroying call '757c8e8e18e9af0f5c584bed200cf1d1@XXX.XXX.XXX.242' asterisk04*CLI> <-- SIP read from XXX.XXX.XXX.12:5060: OPTIONS sip:XXX.XXX.XXX.242 SIP/2.0 Via: SIP/2.0/UDP XXX.XXX.XXX.12:5060;branch=z9hG4bK1ca6dda5;rport From: "asterisk" ;tag=as011b9c09 To: Contact: Call-ID: 46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 09 Apr 2007 19:32:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 0: OPTIONS sip:XXX.XXX.XXX.242 SIP/2.0 (34) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 1: Via: SIP/2.0/UDP XXX.XXX.XXX.12:5060;branch=z9hG4bK1ca6dda5;rport (63) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 2: From: "asterisk" ;tag=as011b9c09 (59) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 3: To: (24) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 4: Contact: (36) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 5: Call-ID: 46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12 (54) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 6: CSeq: 102 OPTIONS (17) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 7: User-Agent: Asterisk PBX (24) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 8: Max-Forwards: 70 (16) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 9: Date: Mon, 09 Apr 2007 19:32:12 GMT (35) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 11: Content-Length: 0 (17) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3447 parse_request: Header 12: (0) --- (12 headers 0 lines) --- Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:3196 sip_alloc: Allocating new SIP dialog for 46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12 - OPTIONS (No RTP) Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:11323 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in from-sip-external (domain XXX.XXX.XXX.242) Transmitting (no NAT) to XXX.XXX.XXX.12:5060: SIP/2.0 404 Not Found Via: SIP/2.0/UDP XXX.XXX.XXX.12:5060;branch=z9hG4bK1ca6dda5;received=XXX.XXX.XXX.12;rport=5060 From: "asterisk" ;tag=as011b9c09 To: ;tag=as25e8df10 Call-ID: 46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Accept: application/sdp Content-Length: 0 --- Apr 9 22:06:14 DEBUG[9157]: chan_sip.c:11527 sipsock_read: SIP message could not be handled, bad request: 46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12 Destroying call '46ce324b7e673abd6eea20507a80e5b1@XXX.XXX.XXX.12' asterisk04*CLI> [root@asterisk04 ~]#