[Dec 4 17:45:03] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'etch' (pid 13789)*CLI> stop nowset verbose 5 Verbosity was 4 and is now 5 *CLI> set verbose 5 5 5 5 5 5 5 5d 5e 5b 5u 5g 5 55 5 55 Core debug was 4 and is now 5 *CLI> sip debug SIP Debugging enabled *CLI> [Dec 4 17:45:08] <-- SIP read from 10.3.67.172:2051: BYE sip:111@10.3.67.195 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kji4s9kcozt9;rport From: "leger" ;tag=xu0z8not4n To: ;tag=as3230aecb Call-ID: 3c39f15b704e-s5bzy59zslz8@snom360-000413231E69 CSeq: 3 BYE Max-Forwards: 70 Contact: ;flow-id=1 User-Agent: snom360/6.5.2 RTP-RxStat: Total_Rx_Pkts=522,Rx_Pkts=522,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=8654,Tx_Pkts=8654,Remote_Tx_Pkts=0 Content-Length: 0 [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: BYE sip:111@10.3.67.195 SIP/2.0 (31) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kji4s9kcozt9;rport (67) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "leger" ;tag=xu0z8not4n (68) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as3230aecb (67) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 3c39f15b704e-s5bzy59zslz8@snom360-000413231E69 (55) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 3 BYE (11) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: User-Agent: snom360/6.5.2 (25) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: RTP-RxStat: Total_Rx_Pkts=522,Rx_Pkts=522,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (78) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: RTP-TxStat: Total_Tx_Pkts=8654,Tx_Pkts=8654,Remote_Tx_Pkts=0 (60) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Content-Length: 0 (17) [Dec 4 17:45:08] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: (0) [Dec 4 17:45:08] --- (12 headers 0 lines) --- [Dec 4 17:45:08] Transmitting (no NAT) to 10.3.67.172:2051: SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kji4s9kcozt9;received=10.3.67.172;rport=2051 From: "leger" ;tag=xu0z8not4n To: ;tag=as3230aecb Call-ID: 3c39f15b704e-s5bzy59zslz8@snom360-000413231E69 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- [Dec 4 17:45:09] <-- SIP read from 10.3.67.172:2051: INVITE sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-w8y2h2yzhltd;rport From: "leger" ;tag=6gzh77z7ip To: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/6.5.2 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 473 v=0 o=root 1883877319 1883877319 IN IP4 10.3.67.172 s=call c=IN IP4 10.3.67.172 t=0 0 m=audio 49678 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:RhglWcMtRMrLcdvVtdT4GtGXbvmBY7nXtPlsUSK4 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 (61) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-w8y2h2yzhltd;rport (67) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "leger" ;tag=6gzh77z7ip (68) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: (52) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 (55) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 INVITE (14) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: User-Agent: snom360/6.5.2 (25) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: Accept: application/sdp (23) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 13: Supported: timer, 100rel, replaces, callerid (44) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 14: Session-Expires: 3600;refresher=uas (35) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 15: Min-SE: 90 (10) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 16: Content-Type: application/sdp (29) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 17: Content-Length: 473 (19) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 18: (0) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: o=root 1883877319 1883877319 IN IP4 10.3.67.172 (47) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: s=call (6) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.3.67.172 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: m=audio 49678 RTP/AVP 0 8 9 2 3 18 4 101 (40) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:RhglWcMtRMrLcdvVtdT4GtGXbvmBY7nXtPlsUSK4 (82) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:9 g722/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 g729/8000 (21) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:4 g723/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=ptime:20 (10) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=encryption:optional (21) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) [Dec 4 17:45:09] --- (18 headers 19 lines) --- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 - INVITE (With RTP) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, callerid" [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -timer- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: timer [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -replaces- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: replaces [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -callerid- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1037 parse_sip_options: Found no match for SIP option: callerid (Please file bug report!) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 7 for call 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 [Dec 4 17:45:09] Using INVITE request as basis request - 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 [Dec 4 17:45:09] Sending to 10.3.67.172 : 2051 (NAT) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0 [Dec 4 17:45:09] Reliably Transmitting (no NAT) to 10.3.67.172:2051: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-w8y2h2yzhltd;received=10.3.67.172;rport=2051 From: "leger" ;tag=6gzh77z7ip To: ;tag=as26b9dae8 Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5dc8d1be" Content-Length: 0 --- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Dec 4 17:45:09] Scheduling destruction of call '3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69' in 15000 ms [Dec 4 17:45:09] Found user 'snom3' [Dec 4 17:45:09] <-- SIP read from 10.3.67.172:2051: ACK sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-w8y2h2yzhltd;rport From: "leger" ;tag=6gzh77z7ip To: ;tag=as26b9dae8 Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: ACK sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 (58) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-w8y2h2yzhltd;rport (67) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "leger" ;tag=6gzh77z7ip (68) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as26b9dae8 (67) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 (55) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 ACK (11) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: (0) [Dec 4 17:45:09] --- (9 headers 0 lines) --- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 Their Tag 6gzh77z7ip Our tag: as26b9dae8 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69' of Response 1: Match Found [Dec 4 17:45:09] <-- SIP read from 10.3.67.172:2051: INVITE sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kll4glkltydo;rport From: "leger" ;tag=6gzh77z7ip To: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 2 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/6.5.2 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Proxy-Authorization: Digest username="snom3",realm="asterisk",nonce="5dc8d1be",uri="sip:111@dyn-195.intranet.gonicus.de;user=phone",response="2b343c8315d647a979c2b19c2ed7ee64",algorithm=md5 Content-Type: application/sdp Content-Length: 473 v=0 o=root 1883877319 1883877319 IN IP4 10.3.67.172 s=call c=IN IP4 10.3.67.172 t=0 0 m=audio 49678 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:RhglWcMtRMrLcdvVtdT4GtGXbvmBY7nXtPlsUSK4 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:111@dyn-195.intranet.gonicus.de;user=phone SIP/2.0 (61) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kll4glkltydo;rport (67) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "leger" ;tag=6gzh77z7ip (68) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: (52) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 (55) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 2 INVITE (14) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: User-Agent: snom360/6.5.2 (25) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: Accept: application/sdp (23) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 13: Supported: timer, 100rel, replaces, callerid (44) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 14: Session-Expires: 3600;refresher=uas (35) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 15: Min-SE: 90 (10) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 16: Proxy-Authorization: Digest username="snom3",realm="asterisk",nonce="5dc8d1be",uri="sip:111@dyn-195.intranet.gonicus.de;user=phone",response="2b343c8315d647a979c2b19c2ed7ee64",algorithm=md5 (189) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 17: Content-Type: application/sdp (29) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 18: Content-Length: 473 (19) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 19: (0) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: o=root 1883877319 1883877319 IN IP4 10.3.67.172 (47) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: s=call (6) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.3.67.172 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: m=audio 49678 RTP/AVP 0 8 9 2 3 18 4 101 (40) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:RhglWcMtRMrLcdvVtdT4GtGXbvmBY7nXtPlsUSK4 (82) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:9 g722/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 g729/8000 (21) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:4 g723/8000 (20) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=ptime:20 (10) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=encryption:optional (21) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) [Dec 4 17:45:09] --- (19 headers 19 lines) --- [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 Their Tag 6gzh77z7ip Our tag: as26b9dae8 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 4 17:45:09] Using INVITE request as basis request - 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 [Dec 4 17:45:09] Sending to 10.3.67.172 : 2051 (NAT) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:7265 check_user_full: Setting NAT on RTP to 0 [Dec 4 17:45:09] Found user 'snom3' [Dec 4 17:45:09] Found RTP audio format 0 [Dec 4 17:45:09] Found RTP audio format 8 [Dec 4 17:45:09] Found RTP audio format 9 [Dec 4 17:45:09] Found RTP audio format 2 [Dec 4 17:45:09] Found RTP audio format 3 [Dec 4 17:45:09] Found RTP audio format 18 [Dec 4 17:45:09] Found RTP audio format 4 [Dec 4 17:45:09] Found RTP audio format 101 [Dec 4 17:45:09] Peer audio RTP is at port 10.3.67.172:49678 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:3668 process_sdp: Peer audio RTP is at port 10.3.67.172:49678 [Dec 4 17:45:09] Found description format pcmu [Dec 4 17:45:09] Found description format pcma [Dec 4 17:45:09] Found description format g722 [Dec 4 17:45:09] Found description format g726-32 [Dec 4 17:45:09] Found description format gsm [Dec 4 17:45:09] Found description format g729 [Dec 4 17:45:09] Found description format g723 [Dec 4 17:45:09] Found description format telephone-event [Dec 4 17:45:09] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x11f (g723|gsm|ulaw|alaw|g726|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Dec 4 17:45:09] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:10632 handle_request_invite: Checking SIP call limits for device snom3 [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call [Dec 4 17:45:09] Looking for 111 in default (domain dyn-195.intranet.gonicus.de;user=phone) [Dec 4 17:45:09] DEBUG[13800]: chan_sip.c:6241 build_route: build_route: Contact hop: ;flow-id=1 [Dec 4 17:45:09] list_route: hop: [Dec 4 17:45:09] Transmitting (no NAT) to 10.3.67.172:2051: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kll4glkltydo;received=10.3.67.172;rport=2051 From: "leger" ;tag=6gzh77z7ip To: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Dec 4 17:45:09] DEBUG[13794]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom3 [Dec 4 17:45:09] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for SIP/snom3 - state 2 (In use) [Dec 4 17:45:09] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' [Dec 4 17:45:09] -- Executing Goto("SIP/snom3-081ae408", "edv|s|1") in new stack [Dec 4 17:45:09] -- Goto (edv,s,1) [Dec 4 17:45:09] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Set' [Dec 4 17:45:09] -- Executing Set("SIP/snom3-081ae408", "LANGUAGE()=de") in new stack [Dec 4 17:45:09] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Ringing' [Dec 4 17:45:09] -- Executing Ringing("SIP/snom3-081ae408", "") in new stack [Dec 4 17:45:09] Transmitting (no NAT) to 10.3.67.172:2051: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kll4glkltydo;received=10.3.67.172;rport=2051 From: "leger" ;tag=6gzh77z7ip To: ;tag=as7f384332 Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Dec 4 17:45:09] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' [Dec 4 17:45:09] -- Executing Wait("SIP/snom3-081ae408", "1") in new stack [Dec 4 17:45:09] DEBUG[13805]: app_queue.c:500 changethread: Device 'SIP/snom3' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:10] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Answer' [Dec 4 17:45:10] -- Executing Answer("SIP/snom3-081ae408", "") in new stack [Dec 4 17:45:10] DEBUG[13804]: chan_sip.c:2560 sip_answer: sip_answer(SIP/snom3-081ae408) [Dec 4 17:45:10] We're at 10.3.67.195 port 19392 [Dec 4 17:45:10] Adding codec 0x4 (ulaw) to SDP [Dec 4 17:45:10] Adding codec 0x8 (alaw) to SDP [Dec 4 17:45:10] Adding non-codec 0x1 (telephone-event) to SDP [Dec 4 17:45:10] Reliably Transmitting (no NAT) to 10.3.67.172:2051: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-kll4glkltydo;received=10.3.67.172;rport=2051 From: "leger" ;tag=6gzh77z7ip To: ;tag=as7f384332 Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 13789 13789 IN IP4 10.3.67.195 s=session c=IN IP4 10.3.67.195 t=0 0 m=audio 19392 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-16 a=silenceSupp:off - - - - --- [Dec 4 17:45:10] DEBUG[13804]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #9 [Dec 4 17:45:10] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Playback' [Dec 4 17:45:10] -- Executing Playback("SIP/snom3-081ae408", "edv") in new stack [Dec 4 17:45:10] WARNING[13804]: file.c:512 ast_openstream_full: File edv does not exist in any format [Dec 4 17:45:10] WARNING[13804]: file.c:824 ast_streamfile: Unable to open edv (format ulaw): No such file or directory [Dec 4 17:45:10] WARNING[13804]: app_playback.c:133 playback_exec: ast_streamfile failed on SIP/snom3-081ae408 for edv [Dec 4 17:45:10] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'SetCIDName' [Dec 4 17:45:10] -- Executing SetCIDName("SIP/snom3-081ae408", "Ueber Hotline") in new stack [Dec 4 17:45:10] WARNING[13804]: app_setcidname.c:71 setcallerid_exec: SetCIDName is deprecated, please use Set(CALLERID(name)=value) instead. [Dec 4 17:45:10] DEBUG[13804]: pbx.c:1677 pbx_extension_helper: Launching 'Queue' [Dec 4 17:45:10] -- Executing Queue("SIP/snom3-081ae408", "edv|tT|300") in new stack [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:3068 queue_exec: NO QUEUE_PRIO variable found. Using default. [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:3076 queue_exec: queue: edv, options: tT, url: 300, announce: (null), expires: 0, priority: 0 [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:1170 join_queue: Queue 'edv' Join, Channel 'SIP/snom3-081ae408', Position '1' [Dec 4 17:45:10] DEBUG[13804]: channel.c:2408 set_format: Set channel SIP/snom3-081ae408 to write format slin [Dec 4 17:45:10] -- Started music on hold, class 'default', on channel 'SIP/snom3-081ae408' [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:2020 is_our_turn: It's our turn (SIP/snom3-081ae408). [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:2215 try_calling: SIP/snom3-081ae408 is trying to call a queue member. [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:10] DEBUG[13804]: app_queue.c:1640 ring_one: Trying 'Agent/130' with metric 0 [Dec 4 17:45:10] DEBUG[13794]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom3 [Dec 4 17:45:10] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for SIP/snom3 - state 2 (In use) [Dec 4 17:45:10] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 2 (In use) [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-7. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-6. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-5. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-4. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-3. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-2. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-1. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-111-1. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Dec 4 17:45:10] DEBUG[13804]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI. [Dec 4 17:45:10] -- outgoing agentcall, to agent '130', on 'Local/106@default-adf7,1' [Dec 4 17:45:10] -- Called Agent/130 [Dec 4 17:45:10] DEBUG[13806]: app_queue.c:500 changethread: Device 'SIP/snom3' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:10] DEBUG[13807]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:10] DEBUG[13808]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' [Dec 4 17:45:10] -- Executing Dial("Local/106@default-adf7,2", "SIP/snom2||tT") in new stack [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0 [Dec 4 17:45:10] DEBUG[13808]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-106-1. [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:2082 sip_call: Outgoing Call for snom2 [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call [Dec 4 17:45:10] We're at 10.3.67.195 port 16936 [Dec 4 17:45:10] Adding codec 0x4 (ulaw) to SDP [Dec 4 17:45:10] Adding codec 0x8 (alaw) to SDP [Dec 4 17:45:10] Adding non-codec 0x1 (telephone-event) to SDP [Dec 4 17:45:10] <-- SIP read from 10.3.67.172:2051: ACK sip:111@10.3.67.195 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-9b2se7866vns;rport From: "leger" ;tag=6gzh77z7ip To: ;tag=as7f384332 Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 CSeq: 2 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:snom2@10.3.67.121:2054;line=viztnhon SIP/2.0 (55) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: ACK sip:111@10.3.67.195 SIP/2.0 (31) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.172:2051;branch=z9hG4bK-9b2se7866vns;rport (67) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "leger" ;tag=6gzh77z7ip (68) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as7f384332 (67) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 (55) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 2 ACK (11) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: (0) [Dec 4 17:45:10] --- (9 headers 0 lines) --- [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3224 find_call: = No match Their Call ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 Their Tag Our tag: as1fe3848d [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69 Their Tag 6gzh77z7ip Our tag: as7f384332 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '3c39f2125cc6-kf2f95t6n3nt@snom360-000413231E69' of Response 2: Match Found [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK361aeed2;rport (62) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as1fe3848d (60) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 3: To: (46) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 4: Contact: (32) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 (53) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 9: Date: Mon, 04 Dec 2006 16:45:10 GMT (35) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 238 (19) [Dec 4 17:45:10] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3427 parse_request: Header 13: (0) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: o=root 13789 13789 IN IP4 10.3.67.195 (37) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: s=session (9) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.3.67.195 (20) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: m=audio 16936 RTP/AVP 0 8 101 (29) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) [Dec 4 17:45:10] 13 headers, 11 lines [Dec 4 17:45:10] Reliably Transmitting (no NAT) to 10.3.67.121:2054: INVITE sip:snom2@10.3.67.121:2054;line=viztnhon SIP/2.0 Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK361aeed2;rport From: "Ueber Hotline" ;tag=as1fe3848d To: Contact: Call-ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 04 Dec 2006 16:45:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 238 v=0 o=root 13789 13789 IN IP4 10.3.67.195 s=session c=IN IP4 10.3.67.195 t=0 0 m=audio 16936 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-16 a=silenceSupp:off - - - - --- [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #10 [Dec 4 17:45:10] -- Called snom2 [Dec 4 17:45:10] <-- SIP read from 10.3.67.121:2054: SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK361aeed2;rport=5060 From: "Ueber Hotline" ;tag=as1fe3848d To: ;tag=6yjfiqymsx Call-ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 CSeq: 102 INVITE Contact: Diversion: ;reason="user-busy" Content-Length: 0 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 302 Moved Temporarily (29) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK361aeed2;rport=5060 (67) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as1fe3848d (60) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=6yjfiqymsx (61) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 (53) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Contact: (46) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Diversion: ;reason="user-busy" (72) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: (0) [Dec 4 17:45:10] --- (9 headers 0 lines) --- [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 Their Tag Our tag: as1fe3848d [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:1391 __sip_ack: Acked pending invite 102 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '79d810c42ae4dbe619c37ff915e100d0@10.3.67.195' of Request 102: Match Found [Dec 4 17:45:10] -- Got SIP response 302 "Moved Temporarily" back from 10.3.67.121 [Dec 4 17:45:10] DEBUG[13800]: chan_sip.c:9657 parse_moved_contact: Found 302 Redirect to extension '111' [Dec 4 17:45:10] Transmitting (no NAT) to 10.3.67.121:2054: ACK sip:snom2@10.3.67.121:2054;line=viztnhon SIP/2.0 Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK361aeed2;rport From: "Ueber Hotline" ;tag=as1fe3848d To: ;tag=6yjfiqymsx Contact: Call-ID: 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Dec 4 17:45:10] -- Now forwarding Local/106@default-adf7,2 to 'Local/111@default' (thanks to SIP/snom2-081b8690) [Dec 4 17:45:10] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use) [Dec 4 17:45:10] DEBUG[13809]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:10] DEBUG[13808]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-106-1. [Dec 4 17:45:10] DEBUG[13808]: channel.c:1367 ast_hangup: Hanging up channel 'SIP/snom2-081b8690' [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:2430 sip_hangup: Hangup call SIP/snom2-081b8690, SIP callid 79d810c42ae4dbe619c37ff915e100d0@10.3.67.195) [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:2438 sip_hangup: update_call_counter(snom2) - decrement call limit counter [Dec 4 17:45:10] DEBUG[13808]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call [Dec 4 17:45:10] DEBUG[13794]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom2 [Dec 4 17:45:10] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for SIP/snom2 - state 1 (Not in use) [Dec 4 17:45:10] DEBUG[13811]: app_queue.c:500 changethread: Device 'SIP/snom2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 4 17:45:10] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Goto' [Dec 4 17:45:10] -- Executing Goto("Local/111@default-38fd,2", "edv|s|1") in new stack [Dec 4 17:45:10] -- Goto (edv,s,1) [Dec 4 17:45:10] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Set' [Dec 4 17:45:10] -- Executing Set("Local/111@default-38fd,2", "LANGUAGE()=de") in new stack [Dec 4 17:45:10] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Ringing' [Dec 4 17:45:10] -- Executing Ringing("Local/111@default-38fd,2", "") in new stack [Dec 4 17:45:10] -- Local/111@default-38fd,1 is ringing [Dec 4 17:45:10] -- Agent/130 is ringing [Dec 4 17:45:10] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' [Dec 4 17:45:10] -- Executing Wait("Local/111@default-38fd,2", "1") in new stack [Dec 4 17:45:10] DEBUG[13804]: channel.c:2030 ast_read: Auto-deactivating generator [Dec 4 17:45:10] DEBUG[13804]: channel.c:2408 set_format: Set channel SIP/snom3-081ae408 to write format ulaw [Dec 4 17:45:10] -- Stopped music on hold on SIP/snom3-081ae408 [Dec 4 17:45:11] Destroying call '79d810c42ae4dbe619c37ff915e100d0@10.3.67.195' [Dec 4 17:45:11] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Answer' [Dec 4 17:45:11] -- Executing Answer("Local/111@default-38fd,2", "") in new stack [Dec 4 17:45:11] DEBUG[13794]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'Local/111@default-38fd,2' [Dec 4 17:45:11] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Playback' [Dec 4 17:45:11] -- Executing Playback("Local/111@default-38fd,2", "edv") in new stack [Dec 4 17:45:11] WARNING[13810]: file.c:512 ast_openstream_full: File edv does not exist in any format [Dec 4 17:45:11] WARNING[13810]: file.c:824 ast_streamfile: Unable to open edv (format ulaw): No such file or directory [Dec 4 17:45:11] WARNING[13810]: app_playback.c:133 playback_exec: ast_streamfile failed on Local/111@default-38fd,2 for edv [Dec 4 17:45:11] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'SetCIDName' [Dec 4 17:45:11] -- Executing SetCIDName("Local/111@default-38fd,2", "Ueber Hotline") in new stack [Dec 4 17:45:11] DEBUG[13810]: pbx.c:1677 pbx_extension_helper: Launching 'Queue' [Dec 4 17:45:11] -- Executing Queue("Local/111@default-38fd,2", "edv|tT|300") in new stack [Dec 4 17:45:11] DEBUG[13810]: app_queue.c:3068 queue_exec: NO QUEUE_PRIO variable found. Using default. [Dec 4 17:45:11] DEBUG[13810]: app_queue.c:3076 queue_exec: queue: edv, options: tT, url: 300, announce: (null), expires: 0, priority: 0 [Dec 4 17:45:11] DEBUG[13810]: app_queue.c:1170 join_queue: Queue 'edv' Join, Channel 'Local/111@default-38fd,2', Position '2' [Dec 4 17:45:11] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format slin [Dec 4 17:45:11] -- Started music on hold, class 'default', on channel 'Local/111@default-38fd,2' [Dec 4 17:45:11] DEBUG[13810]: app_queue.c:2024 is_our_turn: It's not our turn (Local/111@default-38fd,2). [Dec 4 17:45:11] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:11] -- Stopped music on hold on Local/111@default-38fd,2 [Dec 4 17:45:11] DEBUG[13794]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'Local/111@default-38fd,2' [Dec 4 17:45:11] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format gsm [Dec 4 17:45:11] -- Playing 'queue-thereare' (language 'de') [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use) [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 2 (In use) [Dec 4 17:45:11] -- Local/111@default-38fd,1 answered Local/106@default-adf7,2 [Dec 4 17:45:11] DEBUG[13804]: app_queue.c:1953 wait_for_answer: Dunno what to do with control type -1 [Dec 4 17:45:11] -- Agent/130 answered SIP/snom3-081ae408 [Dec 4 17:45:11] DEBUG[13804]: app_queue.c:1673 store_next: Next is 'Agent/129' with metric 1 [Dec 4 17:45:11] DEBUG[13804]: app_queue.c:2401 try_calling: app_queue: sendurl=300. [Dec 4 17:45:11] DEBUG[13794]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'Local/106@default-adf7,2' [Dec 4 17:45:11] WARNING[13804]: chan_local.c:146 local_queue_frame: Local/106@default-adf7,1 wasn't locked while sending 9/1 [Dec 4 17:45:11] DEBUG[13808]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel Local/111@default-38fd,1 into the structure of Local/106@default-adf7,1 [Dec 4 17:45:11] DEBUG[13808]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel Local/111@default-38fd,1 into the structure of Local/106@default-adf7,1 [Dec 4 17:45:11] DEBUG[13808]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/106@default-adf7,2' [Dec 4 17:45:11] DEBUG[13812]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 2 (In use) [Dec 4 17:45:11] DEBUG[13804]: channel.c:2961 ast_do_masquerade: Actually Masquerading Local/111@default-38fd,1(6) into the structure of Local/106@default-adf7,1(6) [Dec 4 17:45:11] DEBUG[13804]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'Local/111@default-38fd,1' at 0x81be8b4 [Dec 4 17:45:11] DEBUG[13804]: channel.c:3154 ast_do_masquerade: Putting channel Local/111@default-38fd,1 in 4/4 formats [Dec 4 17:45:11] DEBUG[13804]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/106@default-adf7,1' [Dec 4 17:45:11] DEBUG[13804]: channel.c:3198 ast_do_masquerade: Done Masquerading Local/111@default-38fd,1 (6) [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Agent/130 - state 3 (Busy) [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 2 (In use) [Dec 4 17:45:11] DEBUG[13813]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13814]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13808]: channel.c:3578 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=Local/106@default-adf7,2, c1=Local/106@default-adf7,1, flags: No,No,Yes,Yes [Dec 4 17:45:11] DEBUG[13808]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/106@default-adf7,2 and Local/106@default-adf7,1 [Dec 4 17:45:11] DEBUG[13808]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/106@default-adf7,1' [Dec 4 17:45:11] DEBUG[13808]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 4 17:45:11] DEBUG[13808]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,106,1) exited non-zero on 'Local/106@default-adf7,2' [Dec 4 17:45:11] == Spawn extension (default, 106, 1) exited non-zero on 'Local/106@default-adf7,2' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" ' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '106' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/106@default-adf7,2' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/111@default-38fd,1' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom2||tT' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:10' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:11' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:11' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165250710.2' [Dec 4 17:45:11] DEBUG[13808]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:11] DEBUG[13808]: channel.c:1367 ast_hangup: Hanging up channel 'Local/106@default-adf7,2' [Dec 4 17:45:11] DEBUG[13815]: app_queue.c:506 changethread: Device 'Agent/130' changed to state '3' (Busy) [Dec 4 17:45:11] DEBUG[13816]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 0 (Unknown) [Dec 4 17:45:11] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/106@default - state 0 (Unknown) [Dec 4 17:45:11] DEBUG[13817]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13818]: app_queue.c:500 changethread: Device 'Local/106@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:11] DEBUG[13804]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 4 17:45:11] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:12] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:13] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:13] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format gsm [Dec 4 17:45:13] -- Playing 'digits/1' (language 'de') [Dec 4 17:45:13] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:13] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:13] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format gsm [Dec 4 17:45:13] -- Playing 'queue-callswaiting' (language 'de') [Dec 4 17:45:14] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:15] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:15] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:15] -- Hold time for edv is 0 minutes 0 seconds [Dec 4 17:45:15] -- Told Local/111@default-38fd,2 in edv their queue position (which was 1) [Dec 4 17:45:15] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format gsm [Dec 4 17:45:15] -- Playing 'queue-thankyou' (language 'de') [Dec 4 17:45:16] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:17] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:17] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format slin [Dec 4 17:45:17] -- Started music on hold, class 'default', on channel 'Local/111@default-38fd,2' [Dec 4 17:45:17] DEBUG[13810]: channel.c:2030 ast_read: Auto-deactivating generator [Dec 4 17:45:17] DEBUG[13810]: channel.c:2408 set_format: Set channel Local/111@default-38fd,2 to write format ulaw [Dec 4 17:45:17] -- Stopped music on hold on Local/111@default-38fd,2 [Dec 4 17:45:17] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:2020 is_our_turn: It's our turn (Local/111@default-38fd,2). [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:2215 try_calling: Local/111@default-38fd,2 is trying to call a queue member. [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:2237 try_calling: Queue with URL=300_ [Dec 4 17:45:18] DEBUG[13810]: app_queue.c:1640 ring_one: Trying 'Agent/129' with metric 1 [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-7. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-6. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-5. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-4. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-3. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-2. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-edv-s-1. [Dec 4 17:45:18] DEBUG[13810]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-111-1. [Dec 4 17:45:18] -- outgoing agentcall, to agent '129', on 'Local/105@default-3653,1' [Dec 4 17:45:18] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use) [Dec 4 17:45:18] -- Called Agent/129 [Dec 4 17:45:18] DEBUG[13819]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' [Dec 4 17:45:18] -- Executing Dial("Local/105@default-3653,2", "SIP/snom1||tT") in new stack [Dec 4 17:45:18] DEBUG[13820]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0 [Dec 4 17:45:18] DEBUG[13819]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-default-105-1. [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:2082 sip_call: Outgoing Call for snom1 [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call [Dec 4 17:45:18] We're at 10.3.67.195 port 15302 [Dec 4 17:45:18] Adding codec 0x4 (ulaw) to SDP [Dec 4 17:45:18] Adding codec 0x8 (alaw) to SDP [Dec 4 17:45:18] Adding non-codec 0x1 (telephone-event) to SDP [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:snom1@10.3.67.149:2051;line=bvnn8r97 SIP/2.0 (55) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport (62) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as3b555078 (60) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 3: To: (46) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 4: Contact: (32) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 9: Date: Mon, 04 Dec 2006 16:45:18 GMT (35) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 238 (19) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3427 parse_request: Header 13: (0) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: o=root 13789 13789 IN IP4 10.3.67.195 (37) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: s=session (9) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.3.67.195 (20) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: m=audio 15302 RTP/AVP 0 8 101 (29) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) [Dec 4 17:45:18] 13 headers, 11 lines [Dec 4 17:45:18] Reliably Transmitting (no NAT) to 10.3.67.149:2051: INVITE sip:snom1@10.3.67.149:2051;line=bvnn8r97 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport From: "Ueber Hotline" ;tag=as3b555078 To: Contact: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 04 Dec 2006 16:45:18 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 238 v=0 o=root 13789 13789 IN IP4 10.3.67.195 s=session c=IN IP4 10.3.67.195 t=0 0 m=audio 15302 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-16 a=silenceSupp:off - - - - --- [Dec 4 17:45:18] DEBUG[13819]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 [Dec 4 17:45:18] -- Called snom1 [Dec 4 17:45:18] <-- SIP read from 10.3.67.149:2051: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 From: "Ueber Hotline" ;tag=as3b555078 To: ;tag=f0yj04qey7 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 (67) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as3b555078 (60) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=f0yj04qey7 (61) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Contact: ;flow-id=1 (61) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 0 (17) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: (0) [Dec 4 17:45:18] --- (10 headers 0 lines) --- [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag Our tag: as3b555078 [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:1458 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #11 - INVITE (got response) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195' Request 102: Found [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite [Dec 4 17:45:18] DEBUG[13794]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom1 [Dec 4 17:45:18] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for SIP/snom1 - state 6 (Ringing) [Dec 4 17:45:18] -- SIP/snom1-081b8690 is ringing [Dec 4 17:45:18] -- Agent/129 is ringing [Dec 4 17:45:18] DEBUG[13821]: app_queue.c:506 changethread: Device 'SIP/snom1' changed to state '6' (Ringing) [Dec 4 17:45:18] <-- SIP read from 10.3.67.149:2051: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 From: "Ueber Hotline" ;tag=as3b555078 To: ;tag=f0yj04qey7 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 (67) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as3b555078 (60) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=f0yj04qey7 (61) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Contact: ;flow-id=1 (61) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 0 (17) [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: (0) [Dec 4 17:45:18] --- (10 headers 0 lines) --- [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195' Request 102: Found [Dec 4 17:45:18] DEBUG[13800]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite [Dec 4 17:45:18] -- SIP/snom1-081b8690 is ringing [Dec 4 17:45:19] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:19] <-- SIP read from 10.3.67.149:2051: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 From: "Ueber Hotline" ;tag=as3b555078 To: ;tag=f0yj04qey7 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 (67) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as3b555078 (60) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=f0yj04qey7 (61) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Contact: ;flow-id=1 (61) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 0 (17) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: (0) [Dec 4 17:45:19] --- (10 headers 0 lines) --- [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195' Request 102: Found [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:9694 handle_response_invite: SIP response 180 to standard invite [Dec 4 17:45:19] -- SIP/snom1-081b8690 is ringing [Dec 4 17:45:19] DEBUG[13819]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:19] <-- SIP read from 10.3.67.149:2051: SIP/2.0 200 Ok Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 From: "Ueber Hotline" ;tag=as3b555078 To: ;tag=f0yj04qey7 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/6.2.2 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 311 v=0 o=root 406436691 406436692 IN IP4 10.3.67.149 s=call c=IN IP4 10.3.67.149 t=0 0 m=audio 52516 RTP/AVP 0 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:mNjVk0M3uc2f7m2BVptffnTbltTxop3yxXImrbqI a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=encryption:optional a=sendrecv [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 Ok (14) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK350a4adb;rport=5060 (67) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: "Ueber Hotline" ;tag=as3b555078 (60) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=f0yj04qey7 (61) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Contact: ;flow-id=1 (61) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: User-Agent: snom360/6.2.2 (25) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 311 (19) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 13: (0) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: o=root 406436691 406436692 IN IP4 10.3.67.149 (45) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: s=call (6) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.3.67.149 (20) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: m=audio 52516 RTP/AVP 0 101 (27) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:mNjVk0M3uc2f7m2BVptffnTbltTxop3yxXImrbqI (82) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=encryption:optional (21) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) [Dec 4 17:45:19] --- (13 headers 12 lines) --- [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:1391 __sip_ack: Acked pending invite 102 [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195' of Request 102: Match Found [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:9694 handle_response_invite: SIP response 200 to standard invite [Dec 4 17:45:19] Found RTP audio format 0 [Dec 4 17:45:19] Found RTP audio format 101 [Dec 4 17:45:19] Peer audio RTP is at port 10.3.67.149:52516 [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:3668 process_sdp: Peer audio RTP is at port 10.3.67.149:52516 [Dec 4 17:45:19] Found description format pcmu [Dec 4 17:45:19] Found description format telephone-event [Dec 4 17:45:19] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 4 17:45:19] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 4 17:45:19] DEBUG[13800]: chan_sip.c:6241 build_route: build_route: Contact hop: ;flow-id=1 [Dec 4 17:45:19] list_route: hop: [Dec 4 17:45:19] set_destination: Parsing for address/port to send to [Dec 4 17:45:19] set_destination: set destination to 10.3.67.149, port 2051 [Dec 4 17:45:19] Transmitting (no NAT) to 10.3.67.149:2051: ACK sip:snom1@10.3.67.149:2051;line=bvnn8r97 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.195:5060;branch=z9hG4bK488be448;rport From: "Ueber Hotline" ;tag=as3b555078 To: ;tag=f0yj04qey7 Contact: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Dec 4 17:45:19] -- SIP/snom1-081b8690 answered Local/105@default-3653,2 [Dec 4 17:45:19] DEBUG[13794]: chan_sip.c:11810 sip_devicestate: Checking device state for peer snom1 [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for SIP/snom1 - state 2 (In use) [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use) [Dec 4 17:45:19] DEBUG[13810]: app_queue.c:1953 wait_for_answer: Dunno what to do with control type -1 [Dec 4 17:45:19] -- Agent/129 answered Local/111@default-38fd,2 [Dec 4 17:45:19] DEBUG[13810]: app_queue.c:1673 store_next: Next is 'Agent/124' with metric 2 [Dec 4 17:45:19] DEBUG[13810]: app_queue.c:2401 try_calling: app_queue: sendurl=300. [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 2 (In use) [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Agent/129 - state 3 (Busy) [Dec 4 17:45:19] DEBUG[13822]: app_queue.c:506 changethread: Device 'SIP/snom1' changed to state '2' (In use) [Dec 4 17:45:19] DEBUG[13823]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:19] DEBUG[13824]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 4 17:45:19] DEBUG[13825]: app_queue.c:506 changethread: Device 'Agent/129' changed to state '3' (Busy) [Dec 4 17:45:19] DEBUG[13819]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 4 17:45:19] DEBUG[13819]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel SIP/snom1-081b8690 into the structure of Local/105@default-3653,1 [Dec 4 17:45:19] DEBUG[13819]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel SIP/snom1-081b8690 into the structure of Local/105@default-3653,1 [Dec 4 17:45:19] DEBUG[13819]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/105@default-3653,2' [Dec 4 17:45:19] DEBUG[13810]: channel.c:2961 ast_do_masquerade: Actually Masquerading SIP/snom1-081b8690(6) into the structure of Local/105@default-3653,1(6) [Dec 4 17:45:19] DEBUG[13810]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'SIP/snom1-081b8690' at 0x81b6414 [Dec 4 17:45:19] DEBUG[13810]: channel.c:3154 ast_do_masquerade: Putting channel SIP/snom1-081b8690 in 4/4 formats [Dec 4 17:45:19] DEBUG[13810]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/105@default-3653,1' [Dec 4 17:45:19] DEBUG[13810]: channel.c:3198 ast_do_masquerade: Done Masquerading SIP/snom1-081b8690 (6) [Dec 4 17:45:19] DEBUG[13810]: chan_agent.c:547 agent_read: Bridge on 'SIP/snom1-081b8690' being set to 'Agent/129' (3) [Dec 4 17:45:19] DEBUG[13819]: channel.c:3380 ast_generic_bridge: Didn't get a frame from channel: Local/105@default-3653,2 [Dec 4 17:45:19] DEBUG[13819]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/105@default-3653,2 and Local/105@default-3653,1 [Dec 4 17:45:19] DEBUG[13819]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/105@default-3653,1' [Dec 4 17:45:19] DEBUG[13819]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 4 17:45:19] DEBUG[13819]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,105,1) exited non-zero on 'Local/105@default-3653,2' [Dec 4 17:45:19] == Spawn extension (default, 105, 1) exited non-zero on 'Local/105@default-3653,2' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" ' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '105' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/105@default-3653,2' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom1-081b8690' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/snom1||tT' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:18' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:19' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:19' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 4 17:45:19] DEBUG[13794]: channel.c:771 channel_find_locked: Avoiding initial deadlock for 'Local/105@default-3653,2' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165250718.8' [Dec 4 17:45:19] DEBUG[13819]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:19] DEBUG[13819]: channel.c:1367 ast_hangup: Hanging up channel 'Local/105@default-3653,2' [Dec 4 17:45:19] DEBUG[13810]: channel.c:2834 ast_channel_masquerade: Planning to masquerade channel Agent/129 into the structure of Local/111@default-38fd,1 [Dec 4 17:45:19] DEBUG[13810]: channel.c:2847 ast_channel_masquerade: Done planning to masquerade channel Agent/129 into the structure of Local/111@default-38fd,1 [Dec 4 17:45:19] DEBUG[13810]: chan_local.c:262 local_write: Not posting to queue since already masked on 'Local/111@default-38fd,2' [Dec 4 17:45:19] DEBUG[13804]: channel.c:2961 ast_do_masquerade: Actually Masquerading Agent/129(6) into the structure of Local/111@default-38fd,1(6) [Dec 4 17:45:19] DEBUG[13804]: channel.c:2972 ast_do_masquerade: Got clone lock for masquerade on 'Agent/129' at 0x81b5c14 [Dec 4 17:45:19] DEBUG[13804]: channel.c:3154 ast_do_masquerade: Putting channel Agent/129 in 4/4 formats [Dec 4 17:45:19] DEBUG[13804]: channel.c:3189 ast_do_masquerade: Released clone lock on 'Local/111@default-38fd,1' [Dec 4 17:45:19] DEBUG[13804]: channel.c:3198 ast_do_masquerade: Done Masquerading Agent/129 (6) [Dec 4 17:45:19] DEBUG[13804]: chan_agent.c:547 agent_read: Bridge on 'Agent/129' being set to 'Agent/130' (3) [Dec 4 17:45:19] DEBUG[13810]: channel.c:3380 ast_generic_bridge: Didn't get a frame from channel: Local/111@default-38fd,2 [Dec 4 17:45:19] DEBUG[13810]: channel.c:3669 ast_channel_bridge: Bridge stops bridging channels Local/111@default-38fd,2 and Local/111@default-38fd,1 [Dec 4 17:45:19] DEBUG[13810]: channel.c:1372 ast_hangup: Hanging up zombie 'Local/111@default-38fd,1' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:2316 __ast_pbx_run: Spawn extension (edv,s,7) exited non-zero on 'Local/111@default-38fd,2' [Dec 4 17:45:19] == Spawn extension (edv, s, 7) exited non-zero on 'Local/111@default-38fd,2' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"Ueber Hotline" ' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'snom3' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 's' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'edv' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Local/111@default-38fd,2' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Agent/129' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Queue' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'edv|tT|300' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:10' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:11' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-12-04 17:45:19' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '9' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '8' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1165250710.6' [Dec 4 17:45:19] DEBUG[13810]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' [Dec 4 17:45:19] DEBUG[13810]: channel.c:1367 ast_hangup: Hanging up channel 'Local/111@default-38fd,2' [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 0 (Unknown) [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/105@default - state 0 (Unknown) [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 0 (Unknown) [Dec 4 17:45:19] DEBUG[13794]: devicestate.c:187 do_state_change: Changing state for Local/111@default - state 0 (Unknown) [Dec 4 17:45:19] DEBUG[13826]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:19] DEBUG[13827]: app_queue.c:500 changethread: Device 'Local/105@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:19] DEBUG[13828]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:19] DEBUG[13829]: app_queue.c:500 changethread: Device 'Local/111@default' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Dec 4 17:45:20] <-- SIP read from 10.3.67.149:2051: INVITE sip:snom3@10.3.67.195 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-6h39qnkkh0yo;rport From: ;tag=f0yj04qey7 To: "Ueber Hotline" ;tag=as3b555078 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/6.2.2 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 467 v=0 o=root 406436691 406436693 IN IP4 10.3.67.149 s=call c=IN IP4 0.0.0.0 t=0 0 m=audio 52516 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:mNjVk0M3uc2f7m2BVptffnTbltTxop3yxXImrbqI a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendonly [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:snom3@10.3.67.195 SIP/2.0 (36) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-6h39qnkkh0yo;rport (67) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=f0yj04qey7 (63) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: "Ueber Hotline" ;tag=as3b555078 (58) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 INVITE (14) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: User-Agent: snom360/6.2.2 (25) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: Accept: application/sdp (23) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: Allow-Events: talk, hold, refer (31) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 13: Supported: timer, 100rel, replaces, callerid (44) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 14: Session-Expires: 3600;refresher=uas (35) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 15: Min-SE: 90 (10) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 16: Content-Type: application/sdp (29) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 17: Content-Length: 467 (19) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 18: (0) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: v=0 (3) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: o=root 406436691 406436693 IN IP4 10.3.67.149 (45) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: s=call (6) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: m=audio 52516 RTP/AVP 0 8 9 2 3 18 4 101 (40) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:mNjVk0M3uc2f7m2BVptffnTbltTxop3yxXImrbqI (82) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:9 g722/8000 (20) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 g729/8000 (21) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:4 g723/8000 (20) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-16 (15) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=ptime:20 (10) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=encryption:optional (21) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3459 parse_request: Line: a=sendonly (10) [Dec 4 17:45:20] --- (18 headers 19 lines) --- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, callerid" [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -timer- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: timer [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -replaces- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1032 parse_sip_options: Matched SIP option: replaces [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1026 parse_sip_options: Found SIP option: -callerid- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1037 parse_sip_options: Found no match for SIP option: callerid (Please file bug report!) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 7 for call 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 [Dec 4 17:45:20] Using INVITE request as basis request - 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 [Dec 4 17:45:20] Sending to 10.3.67.149 : 2051 (NAT) [Dec 4 17:45:20] Found RTP audio format 0 [Dec 4 17:45:20] Found RTP audio format 8 [Dec 4 17:45:20] Found RTP audio format 9 [Dec 4 17:45:20] Found RTP audio format 2 [Dec 4 17:45:20] Found RTP audio format 3 [Dec 4 17:45:20] Found RTP audio format 18 [Dec 4 17:45:20] Found RTP audio format 4 [Dec 4 17:45:20] Found RTP audio format 101 [Dec 4 17:45:20] Peer audio RTP is at port 0.0.0.0:52516 [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3668 process_sdp: Peer audio RTP is at port 0.0.0.0:52516 [Dec 4 17:45:20] Found description format pcmu [Dec 4 17:45:20] Found description format pcma [Dec 4 17:45:20] Found description format g722 [Dec 4 17:45:20] Found description format g726-32 [Dec 4 17:45:20] Found description format gsm [Dec 4 17:45:20] Found description format g729 [Dec 4 17:45:20] Found description format g723 [Dec 4 17:45:20] Found description format telephone-event [Dec 4 17:45:20] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x11f (g723|gsm|ulaw|alaw|g726|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Dec 4 17:45:20] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 4 17:45:20] DEBUG[13800]: channel.c:2408 set_format: Set channel øGí§øGí§1@default-38fd,1 to write format slin [Dec 4 17:45:20] -- Started music on hold, class 'default', on channel 'øGí§øGí§1@default-38fd,1' [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:10676 handle_request_invite: Got a SIP re-invite for call 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 [Dec 4 17:45:20] We're at 10.3.67.195 port 15302 [Dec 4 17:45:20] Adding codec 0x4 (ulaw) to SDP [Dec 4 17:45:20] Adding codec 0x8 (alaw) to SDP [Dec 4 17:45:20] Adding non-codec 0x1 (telephone-event) to SDP [Dec 4 17:45:20] Reliably Transmitting (NAT) to 10.3.67.149:2051: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-6h39qnkkh0yo;received=10.3.67.149;rport=2051 From: ;tag=f0yj04qey7 To: "Ueber Hotline" ;tag=as3b555078 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 13789 13790 IN IP4 10.3.67.195 s=session c=IN IP4 10.3.67.195 t=0 0 m=audio 15302 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-16 a=silenceSupp:off - - - - --- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #12 [Dec 4 17:45:20] <-- SIP read from 10.3.67.149:2051: ACK sip:snom3@10.3.67.195 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-1q2uge51ia2z;rport From: ;tag=f0yj04qey7 To: "Ueber Hotline" ;tag=as3b555078 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: ACK sip:snom3@10.3.67.195 SIP/2.0 (33) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-1q2uge51ia2z;rport (67) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=f0yj04qey7 (63) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: "Ueber Hotline" ;tag=as3b555078 (58) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 ACK (11) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: (0) [Dec 4 17:45:20] --- (9 headers 0 lines) --- [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12 [Dec 4 17:45:20] DEBUG[13800]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195' of Response 1: Match Found [Dec 4 17:45:20] DEBUG[13804]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes [Dec 4 17:45:22] <-- SIP read from 10.3.67.149:2051: REFER sip:snom3@10.3.67.195 SIP/2.0 Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-732mcnsi4fcu;rport From: ;tag=f0yj04qey7 To: "Ueber Hotline" ;tag=as3b555078 Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 CSeq: 2 REFER Max-Forwards: 70 Contact: ;flow-id=1 Refer-To: sip:106@dyn-195.intranet.gonicus.de;user=phone Referred-By: sip:snom1@dyn-195.intranet.gonicus.de User-Agent: snom360/6.2.2 Content-Length: 0 [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 0: REFER sip:snom3@10.3.67.195 SIP/2.0 (35) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.67.149:2051;branch=z9hG4bK-732mcnsi4fcu;rport (67) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=f0yj04qey7 (63) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 3: To: "Ueber Hotline" ;tag=as3b555078 (58) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (53) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 5: CSeq: 2 REFER (13) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 7: Contact: ;flow-id=1 (61) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 8: Refer-To: sip:106@dyn-195.intranet.gonicus.de;user=phone (56) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 9: Referred-By: sip:snom1@dyn-195.intranet.gonicus.de (50) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 10: User-Agent: snom360/6.2.2 (25) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 11: Content-Length: 0 (17) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3427 parse_request: Header 12: (0) [Dec 4 17:45:22] --- (12 headers 0 lines) --- [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:3224 find_call: = Found Their Call ID: 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 Their Tag f0yj04qey7 Our tag: as3b555078 [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:11268 handle_request: **** Received REFER (9) - Command in SIP REFER [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:10782 handle_request_refer: SIP call transfer received for call 76db0f9f2262a8f57db0f8a84fc2d1dc@10.3.67.195 (REFER)! [Dec 4 17:45:22] Transfer to 106 in default [Dec 4 17:45:22] Transfer from snom1 in default [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:6988 get_refer_info: Unsupervised transfer to (Refer-To): 106 [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:6990 get_refer_info: Transferred by (Referred-by: ) snom1 [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:6991 get_refer_info: Transfer Contact Info ;flow-id=1 (REFER_CONTACT) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:10804 handle_request_refer: 202 Accepted (blind) [Dec 4 17:45:22] DEBUG[13800]: chan_sip.c:10809 handle_request_refer: Got SIP blind transfer, applying to 'øGí§øGí§1@default-38fd,1' [Dec 4 17:45:22] DEBUG[13800]: channel.c:2408 set_format: Set channel øGí§øGí§1@default-38fd,1 to write format ulaw [Dec 4 17:45:22] -- Stopped music on hold on øGí§øGí§1@default-38fd,1 [Dec 4 17:45:22] WARNING[13800]: channel.c:2828 ast_channel_masquerade: Can't masquerade channel 'AsyncGoto/AsyncGoto/A' into itself!