[Feb 27 13:26:09] <--- SIP read from 10.0.2.201:5060 ---> INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9ae44889 From: "company | agentur" ;tag=2235be93c54419f9o0 To: Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 101 INVITE Max-Forwards: 70 Contact: "company | agentur" Expires: 240 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 392 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 2182385 2182385 IN IP4 10.0.2.201 s=- c=IN IP4 10.0.2.201 t=0 0 m=audio 5004 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 (38) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9ae44889 (56) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: (29) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 101 INVITE (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Contact: "company | agentur" (64) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Expires: 240 (12) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 392 (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Supported: replaces (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: Content-Type: application/sdp (29) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 14: (0) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=- 2182385 2182385 IN IP4 10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=- (3) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.201 (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5004 RTP/AVP 0 2 4 8 18 96 97 98 101 (44) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:30 (10) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:09] --- (14 headers 18 lines) --- [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for 5d70061b-bd9f3811@10.0.2.201 - INVITE (With RTP) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:1677 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:1685 parse_sip_options: Found SIP option: -replaces- [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:1691 parse_sip_options: Matched SIP option: replaces [Feb 27 13:26:09] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:09] Using INVITE request as basis request - 5d70061b-bd9f3811@10.0.2.201 [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:09] <--- Reliably Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9ae44889;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as3d6254d1 Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="company.at", nonce="3f7b5da7" Content-Length: 0 <------------> [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 [Feb 27 13:26:09] Scheduling destruction of SIP dialog '5d70061b-bd9f3811@10.0.2.201' in 32000 ms (Method: INVITE) [Feb 27 13:26:09] Found user 'vermittlung' [Feb 27 13:26:09] <--- SIP read from 10.0.2.201:5060 ---> ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9ae44889 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as3d6254d1 Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 101 ACK Max-Forwards: 70 Contact: "company | agentur" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 (35) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9ae44889 (56) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as3d6254d1 (44) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 101 ACK (13) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Contact: "company | agentur" (64) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Content-Length: 0 (17) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: (0) [Feb 27 13:26:09] --- (10 headers 0 lines) --- [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '5d70061b-bd9f3811@10.0.2.201' of Response 101: Match Not Found [Feb 27 13:26:09] <--- SIP read from 10.0.2.201:5060 ---> INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-eae6a919 From: "company | agentur" ;tag=2235be93c54419f9o0 To: Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="8b01c9ede8c893e16a6c6a1c087d1645" Contact: "company | agentur" Expires: 240 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 392 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 2182385 2182385 IN IP4 10.0.2.201 s=- c=IN IP4 10.0.2.201 t=0 0 m=audio 5004 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 (38) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-eae6a919 (56) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: (29) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="8b01c9ede8c893e16a6c6a1c087d1645" (176) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Expires: 240 (12) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Content-Length: 392 (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: Supported: replaces (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 14: Content-Type: application/sdp (29) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 15: (0) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=- 2182385 2182385 IN IP4 10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=- (3) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.201 (19) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5004 RTP/AVP 0 2 4 8 18 96 97 98 101 (44) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:30 (10) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:09] --- (15 headers 18 lines) --- [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 13:26:09] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:09] Using INVITE request as basis request - 5d70061b-bd9f3811@10.0.2.201 [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:09] Found user 'vermittlung' [Feb 27 13:26:09] Found RTP audio format 0 [Feb 27 13:26:09] Found RTP audio format 2 [Feb 27 13:26:09] Found RTP audio format 4 [Feb 27 13:26:09] Found RTP audio format 8 [Feb 27 13:26:09] Found RTP audio format 18 [Feb 27 13:26:09] Found RTP audio format 96 [Feb 27 13:26:09] Found RTP audio format 97 [Feb 27 13:26:09] Found RTP audio format 98 [Feb 27 13:26:09] Found RTP audio format 101 [Feb 27 13:26:09] Peer audio RTP is at port 10.0.2.201:5004 [Feb 27 13:26:09] Found description format PCMU for ID 0 [Feb 27 13:26:09] Found description format G726-32 for ID 2 [Feb 27 13:26:09] Found description format G723 for ID 4 [Feb 27 13:26:09] Found description format PCMA for ID 8 [Feb 27 13:26:09] Found description format G729a for ID 18 [Feb 27 13:26:09] Found description format G726-40 for ID 96 [Feb 27 13:26:09] Found description format G726-24 for ID 97 [Feb 27 13:26:09] Found description format G726-16 for ID 98 [Feb 27 13:26:09] Found description format telephone-event for ID 101 [Feb 27 13:26:09] Got unsupported a:fmtp in SDP offer [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:5114 process_sdp: T38 state changed to 0 on channel [Feb 27 13:26:09] Capabilities: us - 0x8 (alaw), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x8 (alaw) [Feb 27 13:26:09] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 27 13:26:09] Peer audio RTP is at port 10.0.2.201:5004 [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:5194 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:13369 handle_request_invite: Checking SIP call limits for device vermittlung [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call [Feb 27 13:26:09] Looking for 0720xxxxxx in intern (domain 10.0.2.5) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3802 sip_new: *** Our native formats are 0x8 (alaw) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x8 (alaw) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x8 (alaw) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:7955 build_route: build_route: Contact hop: "company | agentur" [Feb 27 13:26:09] list_route: hop: [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:13444 handle_request_invite: SIP/vermittlung-08b545d8: New call is still down.... Trying... [Feb 27 13:26:09] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-eae6a919;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:09] DEBUG[8218]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b545d8 [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:09] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:09] DEBUG[8282]: pbx.c:1769 pbx_extension_helper: Launching 'Set' [Feb 27 13:26:09] -- Executing [0720xxxxxx@intern:1] Set("SIP/vermittlung-08b545d8", "CALLERID(number)=+431xxxxxxx") in new stack [Feb 27 13:26:09] DEBUG[8282]: pbx.c:1769 pbx_extension_helper: Launching 'SetCallerPres' [Feb 27 13:26:09] -- Executing [0720xxxxxx@intern:2] SetCallerPres("SIP/vermittlung-08b545d8", "allowed") in new stack [Feb 27 13:26:09] DEBUG[8282]: pbx.c:1769 pbx_extension_helper: Launching 'Dial' [Feb 27 13:26:09] -- Executing [0720xxxxxx@intern:3] Dial("SIP/vermittlung-08b545d8", "IAX2/iax-sil/0720xxxxxx|90|T") in new stack [Feb 27 13:26:09] DEBUG[8282]: rtp.c:1538 ast_rtp_make_compatible: Channel 'IAX2/iax-sil-2' has no RTP, not doing anything [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-intern-0720xxxxxx-3. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-intern-0720xxxxxx-2. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-intern-0720xxxxxx-1. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 27 13:26:09] DEBUG[8282]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 27 13:26:09] DEBUG[8282]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iax-sil-2 [Feb 27 13:26:09] -- Called iax-sil/0720xxxxxx [Feb 27 13:26:09] DEBUG[8282]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to read format slin [Feb 27 13:26:09] DEBUG[8282]: channel.c:2841 set_format: Set channel SIP/vermittlung-08b545d8 to write format slin [Feb 27 13:26:09] DEBUG[8282]: channel.c:2841 set_format: Set channel SIP/vermittlung-08b545d8 to read format slin [Feb 27 13:26:09] DEBUG[8282]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to write format slin [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iax-sil [Feb 27 13:26:09] DEBUG[8210]: chan_iax2.c:9625 iax2_devicestate: Checking device state for device iax-sil [Feb 27 13:26:09] DEBUG[8210]: chan_iax2.c:9633 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iax-sil? addr=-638391339, defaddr=0 maxms=5000, lastms=7 [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for IAX2/iax-sil - state 6 (Ringing) [Feb 27 13:26:09] DEBUG[8283]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:09] DEBUG[8284]: app_queue.c:546 changethread: Device 'IAX2/iax-sil' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 27 13:26:09] -- Call accepted by 213.235.242.217 (format gsm) [Feb 27 13:26:09] -- Format for call is gsm [Feb 27 13:26:09] DEBUG[8282]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iax-sil-2 [Feb 27 13:26:09] -- IAX2/iax-sil-2 answered SIP/vermittlung-08b545d8 [Feb 27 13:26:09] DEBUG[8282]: rtp.c:1474 ast_rtp_early_bridge: Channel 'IAX2/iax-sil-2' has no RTP, not doing anything [Feb 27 13:26:09] DEBUG[8282]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b545d8 [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:3460 sip_answer: SIP answering channel: SIP/vermittlung-08b545d8 [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:6405 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:6173 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:6174 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 27 13:26:09] Audio is at 10.0.2.5 port 16160 [Feb 27 13:26:09] Adding codec 0x8 (alaw) to SDP [Feb 27 13:26:09] Adding non-codec 0x1 (telephone-event) to SDP [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:6305 add_sdp: -- Done with adding codecs to SDP [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:6350 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 27 13:26:09] <--- Reliably Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-eae6a919;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 230 v=0 o=root 8205 8205 IN IP4 10.0.2.5 s=session c=IN IP4 10.0.2.5 t=0 0 m=audio 16160 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 27 13:26:09] DEBUG[8282]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #48 [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iax-sil [Feb 27 13:26:09] DEBUG[8210]: chan_iax2.c:9625 iax2_devicestate: Checking device state for device iax-sil [Feb 27 13:26:09] DEBUG[8210]: chan_iax2.c:9633 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iax-sil? addr=-638391339, defaddr=0 maxms=5000, lastms=7 [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for IAX2/iax-sil - state 2 (In use) [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:09] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:09] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:09] <--- SIP read from 10.0.2.201:5060 ---> ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-d909c139 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="eebb8ee9515296c4d481c6170f564a59" Contact: "company | agentur" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 (35) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-d909c139 (56) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as7b5f94ba (44) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 ACK (13) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="eebb8ee9515296c4d481c6170f564a59" (176) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: (0) [Feb 27 13:26:09] --- (11 headers 0 lines) --- [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #48 [Feb 27 13:26:09] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '5d70061b-bd9f3811@10.0.2.201' of Response 102: Match Not Found [Feb 27 13:26:09] DEBUG[8226]: chan_iax2.c:6638 socket_process: Ooh, voice format changed to 2 [Feb 27 13:26:09] DEBUG[8282]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 27 13:26:09] DEBUG[8282]: rtp.c:2687 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 27 13:26:09] DEBUG[8285]: app_queue.c:546 changethread: Device 'IAX2/iax-sil' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 27 13:26:09] DEBUG[8286]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:13] <--- SIP read from 10.0.2.201:5060 ---> INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-14f48918 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 103 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="8b01c9ede8c893e16a6c6a1c087d1645" Contact: "company | agentur" Expires: 30 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 224 Content-Type: application/sdp v=0 o=- 2182782 2182782 IN IP4 10.0.2.201 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 5004 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendonly <-------------> [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:0720xxxxxx@10.0.2.5 SIP/2.0 (38) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-14f48918 (56) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as7b5f94ba (44) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 103 INVITE (16) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="8b01c9ede8c893e16a6c6a1c087d1645" (176) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Expires: 30 (11) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Content-Length: 224 (19) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: (0) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=- 2182782 2182782 IN IP4 10.0.2.201 (37) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=- (3) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5004 RTP/AVP 0 8 101 (28) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:30 (10) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendonly (10) [Feb 27 13:26:13] --- (13 headers 12 lines) --- [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 13:26:13] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:13] Found RTP audio format 0 [Feb 27 13:26:13] Found RTP audio format 8 [Feb 27 13:26:13] Found RTP audio format 101 [Feb 27 13:26:13] Peer audio RTP is at port 0.0.0.0:5004 [Feb 27 13:26:13] Found description format PCMU for ID 0 [Feb 27 13:26:13] Found description format PCMA for ID 8 [Feb 27 13:26:13] Found description format telephone-event for ID 101 [Feb 27 13:26:13] Got unsupported a:fmtp in SDP offer [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:5114 process_sdp: T38 state changed to 0 on channel SIP/vermittlung-08b545d8 [Feb 27 13:26:13] Capabilities: us - 0x8 (alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Feb 27 13:26:13] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 27 13:26:13] Peer audio RTP is at port 0.0.0.0:5004 [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:5194 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:5201 process_sdp: We have an owner, now see if we need to change this call [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:13422 handle_request_invite: Got a SIP re-invite for call 5d70061b-bd9f3811@10.0.2.201 [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:13517 handle_request_invite: SIP/vermittlung-08b545d8: This call is UP.... [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:6405 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:6173 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:6174 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 27 13:26:13] Audio is at 10.0.2.5 port 16160 [Feb 27 13:26:13] Adding codec 0x8 (alaw) to SDP [Feb 27 13:26:13] Adding non-codec 0x1 (telephone-event) to SDP [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:6305 add_sdp: -- Done with adding codecs to SDP [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:6350 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 27 13:26:13] <--- Reliably Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-14f48918;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 230 v=0 o=root 8205 8206 IN IP4 10.0.2.5 s=session c=IN IP4 10.0.2.5 t=0 0 m=audio 16160 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=recvonly <------------> [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #50 [Feb 27 13:26:13] -- Started music on hold, class 'default', on IAX2/iax-sil-2 [Feb 27 13:26:13] <--- SIP read from 10.0.2.201:5060 ---> ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-fa9cac7 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 103 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="eebb8ee9515296c4d481c6170f564a59" Contact: "company | agentur" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: ACK sip:0720xxxxxx@10.0.2.5 SIP/2.0 (35) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-fa9cac7 (55) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as7b5f94ba (44) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 103 ACK (13) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="eebb8ee9515296c4d481c6170f564a59" (176) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: (0) [Feb 27 13:26:13] --- (11 headers 0 lines) --- [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #50 [Feb 27 13:26:13] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '5d70061b-bd9f3811@10.0.2.201' of Response 103: Match Not Found [Feb 27 13:26:14] DEBUG[8230]: chan_iax2.c:7714 iax2_do_register: Allocate call number [Feb 27 13:26:14] DEBUG[8230]: chan_iax2.c:7720 iax2_do_register: Registration created on call 3 [Feb 27 13:26:15] <--- SIP read from 10.0.2.201:5060 ---> INVITE sip:20@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-620ac2e3 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 101 INVITE Max-Forwards: 70 Contact: "company | agentur" Expires: 240 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 392 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 2182953 2182953 IN IP4 10.0.2.201 s=- c=IN IP4 10.0.2.201 t=0 0 m=audio 5006 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:20@10.0.2.5 SIP/2.0 (30) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-620ac2e3 (56) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 (77) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: (21) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 7836f0e9-be899dd3@10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 101 INVITE (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Contact: "company | agentur" (64) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Expires: 240 (12) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 392 (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Supported: replaces (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: Content-Type: application/sdp (29) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 14: (0) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=- 2182953 2182953 IN IP4 10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=- (3) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.201 (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5006 RTP/AVP 0 2 4 8 18 96 97 98 101 (44) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:30 (10) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:15] --- (14 headers 18 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for 7836f0e9-be899dd3@10.0.2.201 - INVITE (With RTP) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:1677 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:1685 parse_sip_options: Found SIP option: -replaces- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:1691 parse_sip_options: Matched SIP option: replaces [Feb 27 13:26:15] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:15] Using INVITE request as basis request - 7836f0e9-be899dd3@10.0.2.201 [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:15] <--- Reliably Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-620ac2e3;received=10.0.2.201 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: ;tag=as1a9df3ca Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="company.at", nonce="321bf0a9" Content-Length: 0 <------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #51 [Feb 27 13:26:15] Scheduling destruction of SIP dialog '7836f0e9-be899dd3@10.0.2.201' in 32000 ms (Method: INVITE) [Feb 27 13:26:15] Found user 'vermittlung' [Feb 27 13:26:15] <--- SIP read from 10.0.2.201:5060 ---> ACK sip:20@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-620ac2e3 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: ;tag=as1a9df3ca Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 101 ACK Max-Forwards: 70 Contact: "company | agentur" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: ACK sip:20@10.0.2.5 SIP/2.0 (27) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-620ac2e3 (56) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 (77) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as1a9df3ca (36) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 7836f0e9-be899dd3@10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 101 ACK (13) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Contact: "company | agentur" (64) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Content-Length: 0 (17) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: (0) [Feb 27 13:26:15] --- (10 headers 0 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #51 [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '7836f0e9-be899dd3@10.0.2.201' of Response 101: Match Not Found [Feb 27 13:26:15] <--- SIP read from 10.0.2.201:5060 ---> INVITE sip:20@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9258cbd7 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="321bf0a9",uri="sip:20@10.0.2.5",algorithm=MD5,response="79ec6e5b3ebd3d32b7b0f557dadc5861" Contact: "company | agentur" Expires: 240 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 392 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 2182953 2182953 IN IP4 10.0.2.201 s=- c=IN IP4 10.0.2.201 t=0 0 m=audio 5006 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:20@10.0.2.5 SIP/2.0 (30) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9258cbd7 (56) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 (77) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: (21) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 7836f0e9-be899dd3@10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="321bf0a9",uri="sip:20@10.0.2.5",algorithm=MD5,response="79ec6e5b3ebd3d32b7b0f557dadc5861" (168) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Expires: 240 (12) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Content-Length: 392 (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: Supported: replaces (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 14: Content-Type: application/sdp (29) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 15: (0) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=- 2182953 2182953 IN IP4 10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=- (3) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.201 (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5006 RTP/AVP 0 2 4 8 18 96 97 98 101 (44) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:30 (10) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:15] --- (15 headers 18 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 13:26:15] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:15] Using INVITE request as basis request - 7836f0e9-be899dd3@10.0.2.201 [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:15] Found user 'vermittlung' [Feb 27 13:26:15] Found RTP audio format 0 [Feb 27 13:26:15] Found RTP audio format 2 [Feb 27 13:26:15] Found RTP audio format 4 [Feb 27 13:26:15] Found RTP audio format 8 [Feb 27 13:26:15] Found RTP audio format 18 [Feb 27 13:26:15] Found RTP audio format 96 [Feb 27 13:26:15] Found RTP audio format 97 [Feb 27 13:26:15] Found RTP audio format 98 [Feb 27 13:26:15] Found RTP audio format 101 [Feb 27 13:26:15] Peer audio RTP is at port 10.0.2.201:5006 [Feb 27 13:26:15] Found description format PCMU for ID 0 [Feb 27 13:26:15] Found description format G726-32 for ID 2 [Feb 27 13:26:15] Found description format G723 for ID 4 [Feb 27 13:26:15] Found description format PCMA for ID 8 [Feb 27 13:26:15] Found description format G729a for ID 18 [Feb 27 13:26:15] Found description format G726-40 for ID 96 [Feb 27 13:26:15] Found description format G726-24 for ID 97 [Feb 27 13:26:15] Found description format G726-16 for ID 98 [Feb 27 13:26:15] Found description format telephone-event for ID 101 [Feb 27 13:26:15] Got unsupported a:fmtp in SDP offer [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:5114 process_sdp: T38 state changed to 0 on channel [Feb 27 13:26:15] Capabilities: us - 0x8 (alaw), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x8 (alaw) [Feb 27 13:26:15] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 27 13:26:15] Peer audio RTP is at port 10.0.2.201:5006 [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:5194 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:13369 handle_request_invite: Checking SIP call limits for device vermittlung [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call [Feb 27 13:26:15] Looking for 20 in intern (domain 10.0.2.5) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3802 sip_new: *** Our native formats are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:7955 build_route: build_route: Contact hop: "company | agentur" [Feb 27 13:26:15] list_route: hop: [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:13444 handle_request_invite: SIP/vermittlung-08b70368: New call is still down.... Trying... [Feb 27 13:26:15] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9258cbd7;received=10.0.2.201 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:15] DEBUG[8218]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b70368 [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:15] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:15] DEBUG[8287]: pbx.c:1769 pbx_extension_helper: Launching 'Macro' [Feb 27 13:26:15] -- Executing [20@intern:1] Macro("SIP/vermittlung-08b70368", "stdextenint|16|SIP/temp") in new stack [Feb 27 13:26:15] DEBUG[8287]: pbx.c:1769 pbx_extension_helper: Launching 'Answer' [Feb 27 13:26:15] -- Executing [s@macro-stdextenint:1] Answer("SIP/vermittlung-08b70368", "") in new stack [Feb 27 13:26:15] DEBUG[8287]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b70368 [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:15] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3460 sip_answer: SIP answering channel: SIP/vermittlung-08b70368 [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6405 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6173 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6174 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 27 13:26:15] Audio is at 10.0.2.5 port 13282 [Feb 27 13:26:15] Adding codec 0x8 (alaw) to SDP [Feb 27 13:26:15] Adding non-codec 0x1 (telephone-event) to SDP [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6305 add_sdp: -- Done with adding codecs to SDP [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6350 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 27 13:26:15] <--- Reliably Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-9258cbd7;received=10.0.2.201 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: ;tag=as3d3a8440 Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 230 v=0 o=root 8205 8205 IN IP4 10.0.2.5 s=session c=IN IP4 10.0.2.5 t=0 0 m=audio 13282 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #53 [Feb 27 13:26:15] DEBUG[8287]: pbx.c:1769 pbx_extension_helper: Launching 'Dial' [Feb 27 13:26:15] -- Executing [s@macro-stdextenint:2] Dial("SIP/vermittlung-08b70368", "SIP/temp|60|m") in new stack [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:15252 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3802 sip_new: *** Our native formats are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3803 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3804 sip_new: *** Our capabilities are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3805 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3807 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3828 sip_new: This channel will not be able to handle video. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-macro-stdextenint-s-2. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-macro-stdextenint-s-1. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: [Feb 27 13:26:15] <--- SIP read from 10.0.2.201:5060 ---> ACK sip:20@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-8bc8cfc6 From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 To: ;tag=as3d3a8440 Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="321bf0a9",uri="sip:20@10.0.2.5",algorithm=MD5,response="47e7da7c5a7990257f71c83510566a6b" Contact: "company | agentur" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> Not copying variable ARG2. [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: ACK sip:20@10.0.2.5 SIP/2.0 (27) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-8bc8cfc6 (56) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=814fc5f16b1b8c6bo0 (77) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as3d3a8440 (36) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 7836f0e9-be899dd3@10.0.2.201 (37) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 ACK (13) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="321bf0a9",uri="sip:20@10.0.2.5",algorithm=MD5,response="47e7da7c5a7990257f71c83510566a6b" (168) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" (64) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: (0) [Feb 27 13:26:15] --- (11 headers 0 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #53 [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '7836f0e9-be899dd3@10.0.2.201' of Response 102: Match Not Found [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable ARG1. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable STACK-intern-20-1. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 27 13:26:15] DEBUG[8287]: channel.c:3297 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:2827 sip_call: Outgoing Call for temp [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:3000 update_call_counter: Updating call counter for outgoing call [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:2842 sip_call: Our T38 capability (0), joint T38 capability (0) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6173 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6174 add_sdp: ** Our prefcodec: 0x8 (alaw) [Feb 27 13:26:15] Audio is at 10.0.2.5 port 18408 [Feb 27 13:26:15] Adding codec 0x8 (alaw) to SDP [Feb 27 13:26:15] Adding non-codec 0x1 (telephone-event) to SDP [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6305 add_sdp: -- Done with adding codecs to SDP [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:6350 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 0: INVITE sip:temp@10.0.2.200:5066 SIP/2.0 (39) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport (59) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=as068f98c4 (69) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 3: To: (30) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 4: Contact: (35) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 5: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 (50) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 27 13:26:15] DEBUG[8288]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:15] DEBUG[8289]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 9: Date: Tue, 27 Feb 2007 12:26:15 GMT (35) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 11: Supported: replaces (19) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 13: Content-Length: 230 (19) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4562 parse_request: Header 14: (0) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: o=root 8205 8205 IN IP4 10.0.2.5 (32) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: s=session (9) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.5 (17) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: m=audio 18408 RTP/AVP 8 101 (27) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=ptime:20 (10) [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:15] Reliably Transmitting (no NAT) to 10.0.2.200:5066: INVITE sip:temp@10.0.2.200:5066 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport From: "company | agentur" ;tag=as068f98c4 To: Contact: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 27 Feb 2007 12:26:15 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 230 v=0 o=root 8205 8205 IN IP4 10.0.2.5 s=session c=IN IP4 10.0.2.5 t=0 0 m=audio 18408 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 27 13:26:15] DEBUG[8287]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #54 [Feb 27 13:26:15] -- Called temp [Feb 27 13:26:15] <--- SIP read from 10.0.2.200:5066 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport From: "company | agentur" ;tag=as068f98c4 To: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 102 INVITE User-Agent: Grandstream BT110 1.0.8.23 Content-Length: 0 <-------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport (59) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=as068f98c4 (69) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: (30) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 (50) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: User-Agent: Grandstream BT110 1.0.8.23 (38) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: (0) [Feb 27 13:26:15] --- (8 headers 0 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2119 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #54 - INVITE (got response) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2128 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60d19b30343cea451dca9181784fe9b4@10.0.2.5' Request 102: Found [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:11612 handle_response_invite: SIP response 100 to standard invite [Feb 27 13:26:15] <--- SIP read from 10.0.2.200:5066 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport From: "company | agentur" ;tag=as068f98c4 To: ;tag=9fc0f98356aae95d Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 102 INVITE User-Agent: Grandstream BT110 1.0.8.23 Content-Length: 0 <-------------> [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport (59) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=as068f98c4 (69) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=9fc0f98356aae95d (51) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 (50) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: User-Agent: Grandstream BT110 1.0.8.23 (38) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: (0) [Feb 27 13:26:15] --- (8 headers 0 lines) --- [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:2128 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60d19b30343cea451dca9181784fe9b4@10.0.2.5' Request 102: Found [Feb 27 13:26:15] DEBUG[8218]: chan_sip.c:11612 handle_response_invite: SIP response 180 to standard invite [Feb 27 13:26:15] DEBUG[8218]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/temp-08b76030 [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - temp [Feb 27 13:26:15] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer temp [Feb 27 13:26:15] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/temp - state 1 (Not in use) [Feb 27 13:26:15] DEBUG[8290]: app_queue.c:546 changethread: Device 'SIP/temp' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:15] -- Started music on hold, class 'default', on SIP/vermittlung-08b70368 [Feb 27 13:26:15] -- SIP/temp-08b76030 is ringing [Feb 27 13:26:15] DEBUG[8287]: channel.c:2841 set_format: Set channel SIP/vermittlung-08b70368 to write format slin [Feb 27 13:26:15] DEBUG[8287]: res_musiconhold.c:254 ast_moh_files_next: SIP/vermittlung-08b70368 Opened file 0 '/var/lib/asterisk/moh/company/Loop2' [Feb 27 13:26:15] DEBUG[8287]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 27 13:26:15] DEBUG[8287]: rtp.c:2687 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 27 13:26:16] <--- SIP read from 10.0.2.200:5066 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport From: "company | agentur" ;tag=as068f98c4 To: ;tag=9fc0f98356aae95d Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 102 INVITE User-Agent: Grandstream BT110 1.0.8.23 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Supported: replaces Content-Length: 207 v=0 o=temp 8000 8000 IN IP4 10.0.2.200 s=SIP Call c=IN IP4 10.0.2.200 t=0 0 m=audio 5010 RTP/AVP 8 101 a=sendrecv a=rtpmap:8 PCMA/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK0e8d9e13;rport (59) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=as068f98c4 (69) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=9fc0f98356aae95d (51) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 (50) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: User-Agent: Grandstream BT110 1.0.8.23 (38) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Contact: (35) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Content-Type: application/sdp (29) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Supported: replaces (19) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Content-Length: 207 (19) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: (0) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: v=0 (3) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: o=temp 8000 8000 IN IP4 10.0.2.200 (34) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: s=SIP Call (10) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: c=IN IP4 10.0.2.200 (19) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: t=0 0 (5) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: m=audio 5010 RTP/AVP 8 101 (26) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=sendrecv (10) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=ptime:20 (10) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:4594 parse_request: Line: a=fmtp:101 0-11 (15) [Feb 27 13:26:16] --- (12 headers 11 lines) --- [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:2068 __sip_ack: Acked pending invite 102 [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '60d19b30343cea451dca9181784fe9b4@10.0.2.5' of Request 102: Match Not Found [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:11612 handle_response_invite: SIP response 200 to standard invite [Feb 27 13:26:16] Found RTP audio format 8 [Feb 27 13:26:16] Found RTP audio format 101 [Feb 27 13:26:16] Peer audio RTP is at port 10.0.2.200:5010 [Feb 27 13:26:16] Found description format PCMA for ID 8 [Feb 27 13:26:16] Found description format telephone-event for ID 101 [Feb 27 13:26:16] Got unsupported a:fmtp in SDP offer [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:5114 process_sdp: T38 state changed to 0 on channel SIP/temp-08b76030 [Feb 27 13:26:16] Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Feb 27 13:26:16] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 27 13:26:16] Peer audio RTP is at port 10.0.2.200:5010 [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:5194 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:5201 process_sdp: We have an owner, now see if we need to change this call [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:3000 update_call_counter: Updating call counter for outgoing call [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:7955 build_route: build_route: Contact hop: [Feb 27 13:26:16] list_route: hop: [Feb 27 13:26:16] DEBUG[8218]: chan_sip.c:5628 reqprep: Strict routing enforced for session 60d19b30343cea451dca9181784fe9b4@10.0.2.5 [Feb 27 13:26:16] set_destination: Parsing for address/port to send to [Feb 27 13:26:16] set_destination: set destination to 10.0.2.200, port 5066 [Feb 27 13:26:16] Transmitting (no NAT) to 10.0.2.200:5066: ACK sip:temp@10.0.2.200:5066 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK60a814c1;rport From: "company | agentur" ;tag=as068f98c4 To: ;tag=9fc0f98356aae95d Contact: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 13:26:16] -- Call on SIP/temp-08b76030 left from hold [Feb 27 13:26:16] -- Stopped music on hold on SIP/vermittlung-08b70368 [Feb 27 13:26:16] DEBUG[8287]: channel.c:2841 set_format: Set channel SIP/vermittlung-08b70368 to write format alaw [Feb 27 13:26:16] DEBUG[8287]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/temp-08b76030 [Feb 27 13:26:16] -- SIP/temp-08b76030 answered SIP/vermittlung-08b70368 [Feb 27 13:26:16] -- Packet2Packet bridging SIP/vermittlung-08b70368 and SIP/temp-08b76030 [Feb 27 13:26:16] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - temp [Feb 27 13:26:16] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer temp [Feb 27 13:26:16] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/temp - state 1 (Not in use) [Feb 27 13:26:16] DEBUG[8291]: app_queue.c:546 changethread: Device 'SIP/temp' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:17] <--- SIP read from 10.0.2.201:5060 ---> REGISTER sip:10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-51138549 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65935 REGISTER Max-Forwards: 70 Authorization: Digest username="vermittlung",realm="company.at",nonce="5a16ed4d",uri="sip:10.0.2.5",algorithm=MD5,response="ec65e18110d5745e5c2515c504027c77" Contact: "company | agentur" ;expires=60 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces <-------------> [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: REGISTER sip:10.0.2.5 SIP/2.0 (29) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-51138549 (56) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=e12e44407371be16o0 (77) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: "company | agentur" (52) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 81a1527e-db78d426@10.0.2.201 (37) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 65935 REGISTER (20) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Authorization: Digest username="vermittlung",realm="company.at",nonce="5a16ed4d",uri="sip:10.0.2.5",algorithm=MD5,response="ec65e18110d5745e5c2515c504027c77" (159) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" ;expires=60 (75) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Supported: replaces (19) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: (0) [Feb 27 13:26:17] --- (13 headers 0 lines) --- [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4299 sip_alloc: Allocating new SIP dialog for 81a1527e-db78d426@10.0.2.201 - REGISTER (No RTP) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 27 13:26:17] Using latest REGISTER request as basis request [Feb 27 13:26:17] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:17] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-51138549;received=10.0.2.201 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65935 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:17] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-51138549;received=10.0.2.201 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" ;tag=as1bbd06ef Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65935 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="company.at", nonce="02137cb7" Content-Length: 0 <------------> [Feb 27 13:26:17] Scheduling destruction of SIP dialog '81a1527e-db78d426@10.0.2.201' in 32000 ms (Method: REGISTER) [Feb 27 13:26:17] <--- SIP read from 10.0.2.201:5060 ---> REGISTER sip:10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-c27360f9 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65936 REGISTER Max-Forwards: 70 Authorization: Digest username="vermittlung",realm="company.at",nonce="02137cb7",uri="sip:10.0.2.5",algorithm=MD5,response="e874db025f903699c16a4fb3c0dd645f" Contact: "company | agentur" ;expires=60 User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces <-------------> [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: REGISTER sip:10.0.2.5 SIP/2.0 (29) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-c27360f9 (56) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=e12e44407371be16o0 (77) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: "company | agentur" (52) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 81a1527e-db78d426@10.0.2.201 (37) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 65936 REGISTER (20) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Authorization: Digest username="vermittlung",realm="company.at",nonce="02137cb7",uri="sip:10.0.2.5",algorithm=MD5,response="e874db025f903699c16a4fb3c0dd645f" (159) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Contact: "company | agentur" ;expires=60 (75) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Supported: replaces (19) [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: (0) [Feb 27 13:26:17] --- (13 headers 0 lines) --- [Feb 27 13:26:17] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 27 13:26:17] Using latest REGISTER request as basis request [Feb 27 13:26:17] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:17] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-c27360f9;received=10.0.2.201 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65936 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:17] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-c27360f9;received=10.0.2.201 From: "company | agentur" ;tag=e12e44407371be16o0 To: "company | agentur" ;tag=as1bbd06ef Call-ID: 81a1527e-db78d426@10.0.2.201 CSeq: 65936 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Tue, 27 Feb 2007 12:26:17 GMT Content-Length: 0 <------------> [Feb 27 13:26:17] DEBUG[8218]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung [Feb 27 13:26:17] Scheduling destruction of SIP dialog '81a1527e-db78d426@10.0.2.201' in 32000 ms (Method: REGISTER) [Feb 27 13:26:17] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:17] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:17] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:17] DEBUG[8292]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:19] <--- SIP read from 10.0.2.201:5060 ---> REFER sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-e6b16ed1 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Referred-By: "company | agentur" Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 104 REFER Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="781a26e816c2031038b81687f7d57f22" Contact: "company | agentur" Refer-To: User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: REFER sip:0720xxxxxx@10.0.2.5 SIP/2.0 (37) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-e6b16ed1 (56) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as7b5f94ba (44) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Referred-By: "company | agentur" (61) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: CSeq: 104 REFER (15) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Max-Forwards: 70 (16) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="781a26e816c2031038b81687f7d57f22" (176) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Contact: "company | agentur" (64) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Refer-To: (129) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 12: Content-Length: 0 (17) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 13: (0) [Feb 27 13:26:19] --- (13 headers 0 lines) --- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received REFER (9) - Command in SIP REFER [Feb 27 13:26:19] Call 5d70061b-bd9f3811@10.0.2.201 got a SIP call transfer from caller: (REFER)! [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:8687 get_refer_info: Attended transfer: Will use Replace-Call-ID : 7836f0e9-be899dd3@10.0.2.201 (No check of from/to tags) [Feb 27 13:26:19] SIP transfer to extension 20@intern by vermittlung@10.0.2.5 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:13922 handle_request_refer: SIP attended transfer: Transferer channel SIP/vermittlung-08b545d8, transferee channel IAX2/iax-sil-2 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:13938 handle_request_refer: Got SIP transfer, applying to bridged peer 'IAX2/iax-sil-2' [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:8541 get_sip_pvt_byid_locked: Looking for callid 7836f0e9-be899dd3@10.0.2.201 (fromtag 814fc5f16b1b8c6bo0 totag as3d3a8440) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:8565 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 814fc5f16b1b8c6bo0 Our tag is as3d3a8440 [Feb 27 13:26:19] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-e6b16ed1;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 104 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:13693 local_attended_transfer: SIP attended transfer: trying to bridge SIP/vermittlung-08b70368 and IAX2/iax-sil-2 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12703 attempt_transfer: Sip transfer:-------------------- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12705 attempt_transfer: -- Transferer to PBX channel: SIP/vermittlung-08b545d8 State Up [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12709 attempt_transfer: -- Transferer to PBX second channel (target): SIP/vermittlung-08b70368 State Up [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12713 attempt_transfer: -- Bridged call to transferee: IAX2/iax-sil-2 State Up [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12717 attempt_transfer: -- Bridged call to transfer target: SIP/temp-08b76030 State Up [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12720 attempt_transfer: -- END Sip transfer:-------------------- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12728 attempt_transfer: SIP transfer: Four channels to handle [Feb 27 13:26:19] -- Stopped music on hold on IAX2/iax-sil-2 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12759 attempt_transfer: SIP transfer: trying to masquerade IAX2/iax-sil-2 into SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8218]: channel.c:3230 ast_channel_masquerade: Planning to masquerade channel IAX2/iax-sil-2 into the structure of SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8218]: channel.c:3244 ast_channel_masquerade: Done planning to masquerade channel IAX2/iax-sil-2 into the structure of SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:12764 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:5628 reqprep: Strict routing enforced for session 5d70061b-bd9f3811@10.0.2.201 [Feb 27 13:26:19] set_destination: Parsing for address/port to send to [Feb 27 13:26:19] set_destination: set destination to 10.0.2.201, port 5060 [Feb 27 13:26:19] Reliably Transmitting (no NAT) to 10.0.2.201:5060: NOTIFY sip:vermittlung@10.0.2.201:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK43275b26;rport From: ;tag=as7b5f94ba To: "company | agentur" ;tag=2235be93c54419f9o0 Contact: Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=104 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 OK --- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #60 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:13721 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8287]: channel.c:3361 ast_do_masquerade: Actually Masquerading IAX2/iax-sil-2(6) into the structure of SIP/vermittlung-08b70368(6) [Feb 27 13:26:19] DEBUG[8287]: channel.c:3373 ast_do_masquerade: Got clone lock for masquerade on 'IAX2/iax-sil-2' at 0x8b5b280 [Feb 27 13:26:19] DEBUG[8287]: chan_sip.c:3585 sip_fixup: SIP Fixup: New owner for dialogue 7836f0e9-be899dd3@10.0.2.201: IAX2/iax-sil-2 (Old parent: IAX2/iax-sil-2) [Feb 27 13:26:19] DEBUG[8287]: chan_sip.c:3309 sip_hangup: Hangup call IAX2/iax-sil-2, SIP callid 7836f0e9-be899dd3@10.0.2.201) [Feb 27 13:26:19] Scheduling destruction of SIP dialog '7836f0e9-be899dd3@10.0.2.201' in 32000 ms (Method: ACK) [Feb 27 13:26:19] DEBUG[8287]: chan_sip.c:5628 reqprep: Strict routing enforced for session 7836f0e9-be899dd3@10.0.2.201 [Feb 27 13:26:19] set_destination: Parsing for address/port to send to [Feb 27 13:26:19] set_destination: set destination to 10.0.2.201, port 5060 [Feb 27 13:26:19] Reliably Transmitting (no NAT) to 10.0.2.201:5060: BYE sip:vermittlung@10.0.2.201:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK18f0778e;rport From: ;tag=as3d3a8440 To: "company | agentur" ;tag=814fc5f16b1b8c6bo0 Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 13:26:19] DEBUG[8287]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #62 [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to write format alaw [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to read format alaw [Feb 27 13:26:19] DEBUG[8287]: channel.c:3568 ast_do_masquerade: Putting channel IAX2/iax-sil-2 in 8/8 formats [Feb 27 13:26:19] DEBUG[8287]: channel.c:3604 ast_do_masquerade: Released clone lock on 'SIP/vermittlung-08b70368' [Feb 27 13:26:19] DEBUG[8287]: channel.c:3614 ast_do_masquerade: Done Masquerading IAX2/iax-sil-2 (6) [Feb 27 13:26:19] DEBUG[8287]: rtp.c:3038 bridge_p2p_loop: Oooh, something is weird, backing out [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to read format slin [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel SIP/temp-08b76030 to write format slin [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel SIP/temp-08b76030 to read format slin [Feb 27 13:26:19] DEBUG[8287]: channel.c:2841 set_format: Set channel IAX2/iax-sil-2 to write format slin [Feb 27 13:26:19] DEBUG[8282]: channel.c:4015 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/vermittlung-08b545d8, c1=SIP/vermittlung-08b70368, flags: No,No,Yes,Yes [Feb 27 13:26:19] DEBUG[8282]: channel.c:4114 ast_channel_bridge: Bridge stops bridging channels SIP/vermittlung-08b545d8 and SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8282]: channel.c:1694 ast_hangup: Hanging up zombie 'SIP/vermittlung-08b70368' [Feb 27 13:26:19] DEBUG[8282]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b70368 [Feb 27 13:26:19] DEBUG[8282]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 27 13:26:19] DEBUG[8282]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 27 13:26:19] DEBUG[8282]: pbx.c:2367 __ast_pbx_run: Spawn extension (intern,0720xxxxxx,3) exited non-zero on 'SIP/vermittlung-08b545d8' [Feb 27 13:26:19] == Spawn extension (intern, 0720xxxxxx, 3) exited non-zero on 'SIP/vermittlung-08b545d8' [Feb 27 13:26:19] DEBUG[8282]: channel.c:1689 ast_hangup: Hanging up channel 'SIP/vermittlung-08b545d8' [Feb 27 13:26:19] DEBUG[8282]: chan_sip.c:3294 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 5d70061b-bd9f3811@10.0.2.201. [Feb 27 13:26:19] Scheduling destruction of SIP dialog '5d70061b-bd9f3811@10.0.2.201' in 32000 ms (Method: REFER) [Feb 27 13:26:19] DEBUG[8282]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/vermittlung-08b545d8 [Feb 27 13:26:19] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:19] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:19] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:19] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - vermittlung [Feb 27 13:26:19] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer vermittlung [Feb 27 13:26:19] DEBUG[8210]: devicestate.c:287 do_state_change: [Feb 27 13:26:19] <--- SIP read from 10.0.2.201:5060 ---> SIP/2.0 200 OK To: "company | agentur" ;tag=2235be93c54419f9o0 From: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 102 NOTIFY Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK43275b26 Server: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> Changing state for SIP/vermittlung - state 1 (Not in use) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: To: "company | agentur" ;tag=2235be93c54419f9o0 (75) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: ;tag=as7b5f94ba (46) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK43275b26 (53) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Server: Linksys/SPA941-5.1.5 (28) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: (0) [Feb 27 13:26:19] --- (8 headers 0 lines) --- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #60 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '5d70061b-bd9f3811@10.0.2.201' of Request 102: Match Not Found [Feb 27 13:26:19] SIP Response message for INCOMING dialog NOTIFY arrived [Feb 27 13:26:19] <--- SIP read from 10.0.2.201:5060 ---> SIP/2.0 200 OK To: "company | agentur" ;tag=814fc5f16b1b8c6bo0 From: ;tag=as3d3a8440 Call-ID: 7836f0e9-be899dd3@10.0.2.201 CSeq: 102 BYE Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK18f0778e Server: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: To: "company | agentur" ;tag=814fc5f16b1b8c6bo0 (75) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: ;tag=as3d3a8440 (38) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: Call-ID: 7836f0e9-be899dd3@10.0.2.201 (37) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: CSeq: 102 BYE (13) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: Via: SIP/2.0/UDP 10.0.2.5:5060;branch=z9hG4bK18f0778e (53) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Server: Linksys/SPA941-5.1.5 (28) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: (0) [Feb 27 13:26:19] --- (8 headers 0 lines) --- [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62 [Feb 27 13:26:19] DEBUG[8218]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '7836f0e9-be899dd3@10.0.2.201' of Request 102: Match Not Found [Feb 27 13:26:19] SIP Response message for INCOMING dialog BYE arrived [Feb 27 13:26:19] Really destroying SIP dialog '7836f0e9-be899dd3@10.0.2.201' Method: ACK [Feb 27 13:26:19] DEBUG[8287]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 27 13:26:19] DEBUG[8287]: rtp.c:2687 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 27 13:26:20] DEBUG[8293]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:20] DEBUG[8294]: app_queue.c:546 changethread: Device 'SIP/vermittlung' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:23] <--- SIP read from 10.0.2.201:5060 ---> BYE sip:0720xxxxxx@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-af0afc6b From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 105 BYE Max-Forwards: 70 Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="73b5a60818f8b1903e3656c4131701a2" User-Agent: Linksys/SPA941-5.1.5 Content-Length: 0 <-------------> [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: BYE sip:0720xxxxxx@10.0.2.5 SIP/2.0 (35) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-af0afc6b (56) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: "company | agentur" ;tag=2235be93c54419f9o0 (77) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: ;tag=as7b5f94ba (44) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Call-ID: 5d70061b-bd9f3811@10.0.2.201 (37) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: CSeq: 105 BYE (13) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: Proxy-Authorization: Digest username="vermittlung",realm="company.at",nonce="3f7b5da7",uri="sip:0720xxxxxx@10.0.2.5",algorithm=MD5,response="73b5a60818f8b1903e3656c4131701a2" (176) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: User-Agent: Linksys/SPA941-5.1.5 (32) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Content-Length: 0 (17) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: (0) [Feb 27 13:26:23] --- (10 headers 0 lines) --- [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 27 13:26:23] Sending to 10.0.2.201 : 5060 (no NAT) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:1630 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5d70061b-bd9f3811@10.0.2.201 [Feb 27 13:26:23] Scheduling destruction of SIP dialog '5d70061b-bd9f3811@10.0.2.201' in 32000 ms (Method: BYE) [Feb 27 13:26:23] DEBUG[8218]: chan_sip.c:14162 handle_request_bye: Received bye, no owner, selfdestruct soon. [Feb 27 13:26:23] <--- Transmitting (no NAT) to 10.0.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.201:5060;branch=z9hG4bK-af0afc6b;received=10.0.2.201 From: "company | agentur" ;tag=2235be93c54419f9o0 To: ;tag=as7b5f94ba Call-ID: 5d70061b-bd9f3811@10.0.2.201 CSeq: 105 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:25] DEBUG[8218]: chan_sip.c:2007 __sip_autodestruct: Auto destroying SIP dialog '16d39b968c5de09e@10.0.2.200' [Feb 27 13:26:25] DEBUG[8218]: chan_sip.c:3106 sip_destroy: Destroying SIP dialog 16d39b968c5de09e@10.0.2.200 [Feb 27 13:26:25] Really destroying SIP dialog '16d39b968c5de09e@10.0.2.200' Method: REGISTER [Feb 27 13:26:29] <--- SIP read from 10.0.2.200:5066 ---> BYE sip:vermittlung@10.0.2.5 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200:5066;branch=z9hG4bK88344b6f702146bb From: ;tag=9fc0f98356aae95d To: "company | agentur" ;tag=as068f98c4 Supported: replaces Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 7962 BYE User-Agent: Grandstream BT110 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 <-------------> [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 0: BYE sip:vermittlung@10.0.2.5 SIP/2.0 (36) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.2.200:5066;branch=z9hG4bK88344b6f702146bb (63) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 2: From: ;tag=9fc0f98356aae95d (53) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 3: To: "company | agentur" ;tag=as068f98c4 (67) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 4: Supported: replaces (19) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 5: Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 (50) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 6: CSeq: 7962 BYE (14) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 7: User-Agent: Grandstream BT110 1.0.8.23 (38) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 10: Content-Length: 0 (17) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:4562 parse_request: Header 11: (0) [Feb 27 13:26:29] --- (11 headers 0 lines) --- [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:14581 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 27 13:26:29] Sending to 10.0.2.200 : 5066 (no NAT) [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:1630 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 60d19b30343cea451dca9181784fe9b4@10.0.2.5 [Feb 27 13:26:29] DEBUG[8218]: chan_sip.c:14158 handle_request_bye: Received bye, issuing owner hangup [Feb 27 13:26:29] <--- Transmitting (no NAT) to 10.0.2.200:5066 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200:5066;branch=z9hG4bK88344b6f702146bb;received=10.0.2.200 From: ;tag=9fc0f98356aae95d To: "company | agentur" ;tag=as068f98c4 Call-ID: 60d19b30343cea451dca9181784fe9b4@10.0.2.5 CSeq: 7962 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 27 13:26:29] DEBUG[8287]: channel.c:3796 ast_generic_bridge: Didn't get a frame from channel: SIP/temp-08b76030 [Feb 27 13:26:29] DEBUG[8287]: channel.c:4114 ast_channel_bridge: Bridge stops bridging channels IAX2/iax-sil-2 and SIP/temp-08b76030 [Feb 27 13:26:29] DEBUG[8287]: channel.c:1689 ast_hangup: Hanging up channel 'SIP/temp-08b76030' [Feb 27 13:26:29] DEBUG[8287]: chan_sip.c:3309 sip_hangup: Hangup call SIP/temp-08b76030, SIP callid 60d19b30343cea451dca9181784fe9b4@10.0.2.5) [Feb 27 13:26:29] DEBUG[8287]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/temp-08b76030 [Feb 27 13:26:29] DEBUG[8287]: rtp.c:1466 ast_rtp_early_bridge: Channel 'IAX2/iax-sil-2' has no RTP, not doing anything [Feb 27 13:26:29] DEBUG[8287]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 27 13:26:29] DEBUG[8287]: app_macro.c:261 _macro_exec: Spawn extension (macro-stdextenint,s,2) exited non-zero on 'IAX2/iax-sil-2' in macro 'stdextenint' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:2367 __ast_pbx_run: Spawn extension (macro-stdextenint,s,2) exited non-zero on 'IAX2/iax-sil-2' [Feb 27 13:26:29] == Spawn extension (macro-stdextenint, s, 2) exited non-zero on 'IAX2/iax-sil-2' [Feb 27 13:26:29] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - temp [Feb 27 13:26:29] DEBUG[8210]: chan_sip.c:15186 sip_devicestate: Checking device state for peer temp [Feb 27 13:26:29] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for SIP/temp - state 1 (Not in use) [Feb 27 13:26:29] Really destroying SIP dialog '60d19b30343cea451dca9181784fe9b4@10.0.2.5' Method: BYE [Feb 27 13:26:29] DEBUG[8287]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record. [Feb 27 13:26:29] DEBUG[8287]: cdr_addon_mysql.c:226 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,userfield) VALUES ('2007-02-27 13:26:15','vermittlung','vermittlung','20','intern', 'SIP/vermittlung-08b70368','SIP/temp-08b76030','Dial','SIP/temp|60|m',14,14,'ANSWERED',3,'','') [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'vermittlung' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'vermittlung' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '20' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'intern' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/vermittlung-08b70368' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/temp-08b76030' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/temp|60|m' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:15' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:15' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:29' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '14' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '14' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1172579175.2' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 27 13:26:29] DEBUG[8287]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record. [Feb 27 13:26:29] DEBUG[8287]: cdr_addon_mysql.c:226 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,userfield) VALUES ('2007-02-27 13:26:09','vermittlung','vermittlung','20','intern', 'SIP/vermittlung-08b545d8','IAX2/iax-sil-2','Dial','IAX2/iax-sil/0720xxxxxx|90|T',20,20,'ANSWERED',3,'','') [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'vermittlung' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'vermittlung' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '20' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'intern' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/vermittlung-08b545d8' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'IAX2/iax-sil-2' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'IAX2/iax-sil/0720xxxxxx|90|T' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:09' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:09' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-27 13:26:29' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '20' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '20' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1172579169.0' [Feb 27 13:26:29] DEBUG[8287]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 27 13:26:29] DEBUG[8287]: channel.c:1689 ast_hangup: Hanging up channel 'IAX2/iax-sil-2' [Feb 27 13:26:29] DEBUG[8287]: chan_iax2.c:2937 iax2_hangup: We're hanging up IAX2/iax-sil-2 now... [Feb 27 13:26:29] -- Hungup 'IAX2/iax-sil-2' [Feb 27 13:26:29] DEBUG[8287]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iax-sil-2 [Feb 27 13:26:29] DEBUG[8210]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iax-sil [Feb 27 13:26:29] DEBUG[8210]: chan_iax2.c:9625 iax2_devicestate: Checking device state for device iax-sil [Feb 27 13:26:29] DEBUG[8210]: chan_iax2.c:9633 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iax-sil? addr=-638391339, defaddr=0 maxms=5000, lastms=7 [Feb 27 13:26:29] DEBUG[8210]: devicestate.c:287 do_state_change: Changing state for IAX2/iax-sil - state 1 (Not in use) [Feb 27 13:26:29] DEBUG[8295]: app_queue.c:546 changethread: Device 'SIP/temp' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 13:26:29] DEBUG[8296]: app_queue.c:546 changethread: Device 'IAX2/iax-sil' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.