[Jun 9 14:07:58] VERBOSE[24716] logger.c: == Manager 'lmt' logged off from 127.0.0.1 [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.216:5060 ---> INVITE sip:401@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-jnjmct5c86lp;rport From: "Toestel 400" ;tag=vpiiod4wrz To: Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: keys="3" User-Agent: snom320/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 226 v=0 o=root 1296164759 1296164759 IN IP4 192.168.161.216 s=call c=IN IP4 192.168.161.216 t=0 0 m=audio 18876 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:401@pbx.example.net;user=phone SIP/2.0 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-jnjmct5c86lp;rport (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=vpiiod4wrz (60) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: (40) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61723dbade-gpgrmqxnpa8h (34) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 INVITE (14) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: keys="3" (21) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom320/7.1.33 (26) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 16: Content-Type: application/sdp (29) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 17: Content-Length: 226 (19) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 18: (0) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: o=root 1296164759 1296164759 IN IP4 192.168.161.216 (51) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.216 (24) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: m=audio 18876 RTP/AVP 8 101 (27) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (18 headers 11 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 13af400-0-13c4-2c39e-2c5c225e-2c39e Their Tag 13a0260-0-13c4-2c39e-620846bf-2c39e Our tag: as11a0a34d [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26702775b0-f459rxlh8554 Their Tag vpwde33r8q Our tag: as5c719ba7 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c267019cbab-6iju3ec1hvgd Their Tag agr2dig86v Our tag: as483592cb [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad395-ajo6vj1qc0vm Their Tag 97qngh5alh Our tag: as39395c26 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad4c6-phe3ytd26k13 Their Tag hf67o5uhr4 Our tag: as73260cbd [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad52a-gwy8p5tlpim3 Their Tag sjongh64mn Our tag: as56f28897 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad45e-7fxbtgnl1u8t Their Tag tstmut2dxd Our tag: as602e2d77 [Jun 9 14:08:01] DEBUG[23613] acl.c: ##### Testing 192.168.161.216 with 192.168.161.0 [Jun 9 14:08:01] DEBUG[23613] acl.c: ##### Testing 192.168.161.216 with 192.168.200.0 [Jun 9 14:08:01] DEBUG[23613] acl.c: ##### Testing 192.168.161.216 with 192.168.1.0 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Allocating new SIP dialog for 3c61723dbade-gpgrmqxnpa8h - INVITE (With RTP) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Found SIP option: -timer- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Matched SIP option: timer [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Found SIP option: -100rel- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Matched SIP option: 100rel [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Found SIP option: -replaces- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Matched SIP option: replaces [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Found SIP option: -from-change- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Found no match for SIP option: from-change (Please file bug report!) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Sending to 192.168.161.216 : 5060 (NAT) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Using INVITE request as basis request - 3c61723dbade-gpgrmqxnpa8h [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.216:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-jnjmct5c86lp;received=192.168.161.216;rport=5060 From: "Toestel 400" ;tag=vpiiod4wrz To: ;tag=as46016b75 Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 1 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="siprealm", nonce="2f9a9c47" Content-Length: 0 <------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Scheduling destruction of SIP dialog '3c61723dbade-gpgrmqxnpa8h' in 32000 ms (Method: INVITE) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found user '400' [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.216:5060 ---> ACK sip:401@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-jnjmct5c86lp;rport From: "Toestel 400" ;tag=vpiiod4wrz To: ;tag=as46016b75 Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: ACK sip:401@pbx.example.net;user=phone SIP/2.0 (46) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-jnjmct5c86lp;rport (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=vpiiod4wrz (60) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as46016b75 (55) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61723dbade-gpgrmqxnpa8h (34) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 ACK (11) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as46016b75 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1041 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61723dbade-gpgrmqxnpa8h' of Response 1: Match Found [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.216:5060 ---> INVITE sip:401@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-8zffo976t9w7;rport From: "Toestel 400" ;tag=vpiiod4wrz To: Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 2 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: keys="3" User-Agent: snom320/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Proxy-Authorization: Digest username="400",realm="siprealm",nonce="2f9a9c47",uri="sip:401@pbx.example.net;user=phone",response="7e82a9f19f126fae0b859cad343d1689",algorithm=MD5 Content-Type: application/sdp Content-Length: 226 v=0 o=root 1296164759 1296164759 IN IP4 192.168.161.216 s=call c=IN IP4 192.168.161.216 t=0 0 m=audio 18876 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:401@pbx.example.net;user=phone SIP/2.0 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-8zffo976t9w7;rport (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=vpiiod4wrz (60) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: (40) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61723dbade-gpgrmqxnpa8h (34) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: keys="3" (21) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom320/7.1.33 (26) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 16: Proxy-Authorization: Digest username="400",realm="siprealm",nonce="2f9a9c47",uri="sip:401@pbx.example.net;user=phone",response="7e82a9f19f126fae0b859cad343d1689",algorithm=MD5 (175) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 17: Content-Type: application/sdp (29) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 18: Content-Length: 226 (19) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 19: (0) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: o=root 1296164759 1296164759 IN IP4 192.168.161.216 (51) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.216 (24) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: m=audio 18876 RTP/AVP 8 101 (27) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (19 headers 11 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as46016b75 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:01] VERBOSE[23613] logger.c: Sending to 192.168.161.216 : 5060 (NAT) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Using INVITE request as basis request - 3c61723dbade-gpgrmqxnpa8h [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found user '400' [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 9 14:08:01] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.216:18876 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel [Jun 9 14:08:01] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:01] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.216:18876 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Checking SIP call limits for device 400 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Updating call counter for incoming call [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Call from peer '400' is 1 out of 30 [Jun 9 14:08:01] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/400 [Jun 9 14:08:01] VERBOSE[23613] logger.c: Looking for 401 in user-01 (domain pbx.example.net) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: This channel will not be able to handle video. [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: build_route: Contact hop: ;flow-id=1 [Jun 9 14:08:01] VERBOSE[23613] logger.c: list_route: hop: [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: SIP/400-08825f48: New call is still down.... Trying... [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- Transmitting (no NAT) to 192.168.161.216:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-8zffo976t9w7;received=192.168.161.216;rport=5060 From: "Toestel 400" ;tag=vpiiod4wrz To: Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:01] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/400-08825f48 [Jun 9 14:08:01] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/400 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/400 - state 2 (In use) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:01] VERBOSE[23576] logger.c: Reliably Transmitting (no NAT) to 192.168.161.250:5060: NOTIFY sip:401@192.168.161.250:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK505ea0ce;rport From: ;tag=as39395c26 To: ;tag=97qngh5alh Contact: Call-ID: 3c26701ad395-ajo6vj1qc0vm CSeq: 117 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 206 confirmed --- [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:01] VERBOSE[23576] logger.c: Extension Changed 400[subscriptions] new state InUse for Notify User 401 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400-08825f48 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400-08825f48 [Jun 9 14:08:01] DEBUG[24774] pbx.c: Launching 'Dial' [Jun 9 14:08:01] VERBOSE[24774] logger.c: -- Executing [401@user-01:1] Dial("SIP/400-08825f48", "SIP/401") in new stack [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:01] DEBUG[24774] acl.c: ##### Testing 192.168.161.250 with 192.168.161.0 [Jun 9 14:08:01] DEBUG[24774] acl.c: ##### Testing 192.168.161.250 with 192.168.200.0 [Jun 9 14:08:01] DEBUG[24774] acl.c: ##### Testing 192.168.161.250 with 192.168.1.0 [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: This channel will not be able to handle video. [Jun 9 14:08:01] DEBUG[24774] channel.c: Not copying variable SIPCALLID. [Jun 9 14:08:01] DEBUG[24774] channel.c: Not copying variable SIPUSERAGENT. [Jun 9 14:08:01] DEBUG[24774] channel.c: Not copying variable SIPDOMAIN. [Jun 9 14:08:01] DEBUG[24774] channel.c: Not copying variable SIPURI. [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Outgoing Call for 401 [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Updating call counter for outgoing call [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Call to peer '401' is 1 out of 30 [Jun 9 14:08:01] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 9 14:08:01] VERBOSE[24774] logger.c: Audio is at 192.168.161.100 port 10552 [Jun 9 14:08:01] VERBOSE[24774] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:01] VERBOSE[24774] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:01] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 0: INVITE sip:401@192.168.161.250:5060 SIP/2.0 (43) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport (66) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 2: From: "Toestel 400" ;tag=as3c18a7ab (60) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 3: To: (34) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 4: Contact: (34) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 5: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 7: User-Agent: atCOM PBX (21) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 9: Remote-Party-ID: "Toestel 400" ;privacy=off;screen=no (78) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 10: Date: Mon, 09 Jun 2008 12:08:01 GMT (35) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 12: Supported: replaces (19) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 14: Content-Length: 246 (19) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Header 15: (0) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: o=root 23546 23546 IN IP4 192.168.161.100 (41) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: s=session (9) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: c=IN IP4 192.168.161.100 (24) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: m=audio 10552 RTP/AVP 8 101 (27) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:01] VERBOSE[24774] logger.c: Reliably Transmitting (no NAT) to 192.168.161.250:5060: INVITE sip:401@192.168.161.250:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport From: "Toestel 400" ;tag=as3c18a7ab To: Contact: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 102 INVITE User-Agent: atCOM PBX Max-Forwards: 70 Remote-Party-ID: "Toestel 400" ;privacy=off;screen=no Date: Mon, 09 Jun 2008 12:08:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23546 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 10552 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 9 14:08:01] DEBUG[24774] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:01] VERBOSE[24774] logger.c: -- Called 401 [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/400' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/400-08825f48 - state 4 (Invalid) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/400 - state 2 (In use) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 6 (Ringing) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/400-08825f48' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/400' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK505ea0ce;rport=5060 From: ;tag=as39395c26 To: ;tag=97qngh5alh Call-ID: 3c26701ad395-ajo6vj1qc0vm CSeq: 117 NOTIFY Content-Length: 0 <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 200 Ok (14) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK505ea0ce;rport=5060 (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=as39395c26 (57) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=97qngh5alh (44) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c26701ad395-ajo6vj1qc0vm (34) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 117 NOTIFY (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Content-Length: 0 (17) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: (0) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (7 headers 0 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag Our tag: as3c18a7ab [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as5d44649b [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 13af400-0-13c4-2c39e-2c5c225e-2c39e Their Tag 13a0260-0-13c4-2c39e-620846bf-2c39e Our tag: as11a0a34d [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26702775b0-f459rxlh8554 Their Tag vpwde33r8q Our tag: as5c719ba7 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c267019cbab-6iju3ec1hvgd Their Tag agr2dig86v Our tag: as483592cb [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c26701ad395-ajo6vj1qc0vm Their Tag 97qngh5alh Our tag: as39395c26 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Acked pending invite 117 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1043 [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c26701ad395-ajo6vj1qc0vm' of Request 117: Match Found [Jun 9 14:08:01] VERBOSE[23613] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=as3c18a7ab (60) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ldxuvi1dse (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 9: Content-Length: 0 (17) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 10: (0) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (10 headers 0 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag Our tag: as3c18a7ab [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: *** SIP TIMER: Cancelling retransmission #1044 - INVITE (got response) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '194a081732806989569ccf6c70db082b@pbx.example.net' Request 102: Found [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: SIP response 180 to standard invite [Jun 9 14:08:01] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08820780 [Jun 9 14:08:01] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:01] VERBOSE[24774] logger.c: -- SIP/401-08820780 is ringing [Jun 9 14:08:01] VERBOSE[24774] logger.c: <--- Transmitting (no NAT) to 192.168.161.216:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-8zffo976t9w7;received=192.168.161.216;rport=5060 From: "Toestel 400" ;tag=vpiiod4wrz To: ;tag=as5d44649b Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08820780 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08820780 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/401-08820780 - state 4 (Invalid) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:01] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 6 (Ringing) [Jun 9 14:08:01] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:01] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/401-08820780' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 9 14:08:01] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 (71) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=as3c18a7ab (60) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ldxuvi1dse (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 9: Content-Length: 0 (17) [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: Header 10: (0) [Jun 9 14:08:01] VERBOSE[23613] logger.c: --- (10 headers 0 lines) --- [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '194a081732806989569ccf6c70db082b@pbx.example.net' Request 102: Found [Jun 9 14:08:01] DEBUG[23613] chan_sip.c: SIP response 180 to standard invite [Jun 9 14:08:01] VERBOSE[24774] logger.c: -- SIP/401-08820780 is ringing [Jun 9 14:08:02] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/7.1.33 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Content-Type: application/sdp Content-Length: 226 v=0 o=root 1253804504 1253804505 IN IP4 192.168.161.250 s=call c=IN IP4 192.168.161.250 t=0 0 m=audio 17644 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 200 Ok (14) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK30075162;rport=5060 (71) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=as3c18a7ab (60) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ldxuvi1dse (49) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 7: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 9: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 10: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 11: Content-Type: application/sdp (29) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 12: Content-Length: 226 (19) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 13: (0) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: o=root 1253804504 1253804505 IN IP4 192.168.161.250 (51) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.250 (24) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: m=audio 17644 RTP/AVP 8 101 (27) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:02] VERBOSE[23613] logger.c: --- (13 headers 11 lines) --- [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Acked pending invite 102 [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Stopping retransmission on '194a081732806989569ccf6c70db082b@pbx.example.net' of Request 102: Match Found [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: SIP response 200 to standard invite [Jun 9 14:08:02] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:17644 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel SIP/401-08820780 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:02] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:02] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:17644 [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: We have an owner, now see if we need to change this call [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Updating call counter for outgoing call [Jun 9 14:08:02] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: build_route: Contact hop: ;flow-id=1 [Jun 9 14:08:02] VERBOSE[23613] logger.c: list_route: hop: [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Strict routing enforced for session 194a081732806989569ccf6c70db082b@pbx.example.net [Jun 9 14:08:02] VERBOSE[23613] logger.c: set_destination: Parsing for address/port to send to [Jun 9 14:08:02] VERBOSE[23613] logger.c: set_destination: set destination to 192.168.161.250, port 5060 [Jun 9 14:08:02] VERBOSE[23613] logger.c: Transmitting (no NAT) to 192.168.161.250:5060: ACK sip:401@192.168.161.250:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK48776a13;rport From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Contact: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 102 ACK User-Agent: atCOM PBX Max-Forwards: 70 Remote-Party-ID: "Toestel 400" ;privacy=off;screen=no Content-Length: 0 --- [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:02] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:02] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08820780 [Jun 9 14:08:02] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:02] VERBOSE[24774] logger.c: -- SIP/401-08820780 answered SIP/400-08825f48 [Jun 9 14:08:02] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/400-08825f48 [Jun 9 14:08:02] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/400 [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: SIP answering channel: SIP/400-08825f48 [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: Setting framing from config on incoming call [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 9 14:08:02] VERBOSE[24774] logger.c: Audio is at 192.168.161.100 port 13716 [Jun 9 14:08:02] VERBOSE[24774] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:02] VERBOSE[24774] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:02] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:02] VERBOSE[24774] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.216:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-8zffo976t9w7;received=192.168.161.216;rport=5060 From: "Toestel 400" ;tag=vpiiod4wrz To: ;tag=as5d44649b Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23546 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 13716 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 9 14:08:02] DEBUG[24774] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:02] VERBOSE[24774] logger.c: -- Packet2Packet bridging SIP/400-08825f48 and SIP/401-08820780 [Jun 9 14:08:02] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08820780 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08820780 [Jun 9 14:08:02] DEBUG[23576] devicestate.c: Changing state for SIP/401-08820780 - state 4 (Invalid) [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:02] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400-08825f48 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 400-08825f48 [Jun 9 14:08:02] DEBUG[23615] app_queue.c: Device 'SIP/401-08820780' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:02] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:02] DEBUG[23576] devicestate.c: Changing state for SIP/400-08825f48 - state 4 (Invalid) [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:02] DEBUG[23576] devicestate.c: Changing state for SIP/400 - state 2 (In use) [Jun 9 14:08:02] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Jun 9 14:08:02] DEBUG[23576] chan_sip.c: Checking device state for peer 400 [Jun 9 14:08:02] DEBUG[23615] app_queue.c: Device 'SIP/400-08825f48' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:02] DEBUG[23615] app_queue.c: Device 'SIP/400' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:02] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.216:5060 ---> ACK sip:401@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-9tkigrmnb8zo;rport From: "Toestel 400" ;tag=vpiiod4wrz To: ;tag=as5d44649b Call-ID: 3c61723dbade-gpgrmqxnpa8h CSeq: 2 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 0: ACK sip:401@192.168.161.100 SIP/2.0 (35) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.216:5060;branch=z9hG4bK-9tkigrmnb8zo;rport (71) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=vpiiod4wrz (60) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as5d44649b (55) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61723dbade-gpgrmqxnpa8h (34) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 5: CSeq: 2 ACK (11) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:02] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: = No match Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as5d44649b [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1046 [Jun 9 14:08:02] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61723dbade-gpgrmqxnpa8h' of Response 2: Match Found [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Auto destroying SIP dialog '3c267019cbab-6iju3ec1hvgd' [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Destroying SIP dialog 3c267019cbab-6iju3ec1hvgd [Jun 9 14:08:05] VERBOSE[23613] logger.c: Really destroying SIP dialog '3c267019cbab-6iju3ec1hvgd' Method: REGISTER [Jun 9 14:08:05] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> INVITE sip:400@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-fxjywdh0jgez;rport From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 226 v=0 o=root 1253804504 1253804506 IN IP4 192.168.161.250 s=call c=IN IP4 192.168.161.250 t=0 0 m=audio 17644 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendonly <-------------> [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:400@192.168.161.100 SIP/2.0 (38) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-fxjywdh0jgez;rport (71) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=ldxuvi1dse (51) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 3: To: "Toestel 400" ;tag=as3c18a7ab (58) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 INVITE (14) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 16: Content-Type: application/sdp (29) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 17: Content-Length: 226 (19) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 18: (0) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: o=root 1253804504 1253804506 IN IP4 192.168.161.250 (51) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.250 (24) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: m=audio 17644 RTP/AVP 8 101 (27) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Line: a=sendonly (10) [Jun 9 14:08:05] VERBOSE[23613] logger.c: --- (18 headers 11 lines) --- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Found SIP option: -timer- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Matched SIP option: timer [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Found SIP option: -100rel- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Matched SIP option: 100rel [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Found SIP option: -replaces- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Matched SIP option: replaces [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Found SIP option: -from-change- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Found no match for SIP option: from-change (Please file bug report!) [Jun 9 14:08:05] VERBOSE[23613] logger.c: Sending to 192.168.161.250 : 5060 (NAT) [Jun 9 14:08:05] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:17644 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel SIP/401-08820780 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:05] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:05] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:17644 [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: We have an owner, now see if we need to change this call [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Got a SIP re-invite for call 194a081732806989569ccf6c70db082b@pbx.example.net [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: SIP/401-08820780: This call is UP.... [Jun 9 14:08:05] VERBOSE[23613] logger.c: <--- Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-fxjywdh0jgez;received=192.168.161.250;rport=5060 From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 1 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Setting framing from config on incoming call [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 9 14:08:05] VERBOSE[23613] logger.c: Audio is at 192.168.161.100 port 10552 [Jun 9 14:08:05] VERBOSE[23613] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:05] VERBOSE[23613] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:05] DEBUG[23613] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=30) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:05] VERBOSE[23613] logger.c: <--- Reliably Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-fxjywdh0jgez;received=192.168.161.250;rport=5060 From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 1 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23547 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 10552 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=recvonly <------------> [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:05] VERBOSE[24774] logger.c: -- Started music on hold, class 'default', on SIP/400-08825f48 [Jun 9 14:08:05] DEBUG[24774] channel.c: Scheduling timer at 160 sample intervals [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Generator got voice, switching to phase locked mode [Jun 9 14:08:05] DEBUG[24774] channel.c: Scheduling timer at 0 sample intervals [Jun 9 14:08:05] DEBUG[24774] res_musiconhold.c: SIP/400-08825f48 Opened file 1 '/var/lib/asterisk/moh/default/calm-river' [Jun 9 14:08:05] DEBUG[24774] rtp.c: Ooh, format changed from unknown to alaw [Jun 9 14:08:05] DEBUG[24774] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> ACK sip:400@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0yr38panhvc5;rport From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 0: ACK sip:400@192.168.161.100 SIP/2.0 (35) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0yr38panhvc5;rport (71) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=ldxuvi1dse (51) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 3: To: "Toestel 400" ;tag=as3c18a7ab (58) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 ACK (11) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:05] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1047 [Jun 9 14:08:05] DEBUG[23613] chan_sip.c: Stopping retransmission on '194a081732806989569ccf6c70db082b@pbx.example.net' of Response 1: Match Found [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:05] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> INVITE sip:402@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-15svozbwjs3z;rport From: "Toestel 401" ;tag=4xerru1alm To: Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 1 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 222 v=0 o=root 84706495 84706495 IN IP4 192.168.161.250 s=call c=IN IP4 192.168.161.250 t=0 0 m=audio 18992 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:402@pbx.example.net;user=phone SIP/2.0 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-15svozbwjs3z;rport (71) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 3: To: (40) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 INVITE (14) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 16: Content-Type: application/sdp (29) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 17: Content-Length: 222 (19) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 18: (0) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: o=root 84706495 84706495 IN IP4 192.168.161.250 (47) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.250 (24) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: m=audio 18992 RTP/AVP 8 101 (27) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:06] VERBOSE[23613] logger.c: --- (18 headers 11 lines) --- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as5d44649b [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 13af400-0-13c4-2c39e-2c5c225e-2c39e Their Tag 13a0260-0-13c4-2c39e-620846bf-2c39e Our tag: as11a0a34d [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26702775b0-f459rxlh8554 Their Tag vpwde33r8q Our tag: as5c719ba7 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad395-ajo6vj1qc0vm Their Tag 97qngh5alh Our tag: as39395c26 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad4c6-phe3ytd26k13 Their Tag hf67o5uhr4 Our tag: as73260cbd [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad52a-gwy8p5tlpim3 Their Tag sjongh64mn Our tag: as56f28897 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad45e-7fxbtgnl1u8t Their Tag tstmut2dxd Our tag: as602e2d77 [Jun 9 14:08:06] DEBUG[23613] acl.c: ##### Testing 192.168.161.250 with 192.168.161.0 [Jun 9 14:08:06] DEBUG[23613] acl.c: ##### Testing 192.168.161.250 with 192.168.200.0 [Jun 9 14:08:06] DEBUG[23613] acl.c: ##### Testing 192.168.161.250 with 192.168.1.0 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Allocating new SIP dialog for 3c61727a6d72-hngk6cx7x17v - INVITE (With RTP) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Found SIP option: -timer- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Matched SIP option: timer [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Found SIP option: -100rel- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Matched SIP option: 100rel [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Found SIP option: -replaces- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Matched SIP option: replaces [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Found SIP option: -from-change- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Found no match for SIP option: from-change (Please file bug report!) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Sending to 192.168.161.250 : 5060 (NAT) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Using INVITE request as basis request - 3c61727a6d72-hngk6cx7x17v [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.250:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-15svozbwjs3z;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as5c743fa4 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 1 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="siprealm", nonce="2ec45dca" Content-Length: 0 <------------> [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Scheduling destruction of SIP dialog '3c61727a6d72-hngk6cx7x17v' in 32000 ms (Method: INVITE) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found user '401' [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> ACK sip:402@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-15svozbwjs3z;rport From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as5c743fa4 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 0: ACK sip:402@pbx.example.net;user=phone SIP/2.0 (46) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-15svozbwjs3z;rport (71) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as5c743fa4 (55) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 5: CSeq: 1 ACK (11) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:06] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as5c743fa4 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1049 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61727a6d72-hngk6cx7x17v' of Response 1: Match Found [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> INVITE sip:402@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-9cu0tf8ogg2b;rport From: "Toestel 401" ;tag=4xerru1alm To: Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 2 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Proxy-Authorization: Digest username="401",realm="siprealm",nonce="2ec45dca",uri="sip:402@pbx.example.net;user=phone",response="5a0063b9ab61d51f2205a487b3181497",algorithm=MD5 Content-Type: application/sdp Content-Length: 222 v=0 o=root 84706495 84706495 IN IP4 192.168.161.250 s=call c=IN IP4 192.168.161.250 t=0 0 m=audio 18992 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:402@pbx.example.net;user=phone SIP/2.0 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-9cu0tf8ogg2b;rport (71) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 3: To: (40) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 16: Proxy-Authorization: Digest username="401",realm="siprealm",nonce="2ec45dca",uri="sip:402@pbx.example.net;user=phone",response="5a0063b9ab61d51f2205a487b3181497",algorithm=MD5 (175) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 17: Content-Type: application/sdp (29) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 18: Content-Length: 222 (19) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 19: (0) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: o=root 84706495 84706495 IN IP4 192.168.161.250 (47) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.250 (24) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: m=audio 18992 RTP/AVP 8 101 (27) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:06] VERBOSE[23613] logger.c: --- (19 headers 11 lines) --- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as5c743fa4 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:06] VERBOSE[23613] logger.c: Sending to 192.168.161.250 : 5060 (NAT) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Using INVITE request as basis request - 3c61727a6d72-hngk6cx7x17v [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on VRTP to Off [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Setting NAT on UDPTL to Off [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found user '401' [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 9 14:08:06] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:18992 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel [Jun 9 14:08:06] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:06] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:18992 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Checking SIP call limits for device 401 [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Updating call counter for incoming call [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Call from peer '401' is 2 out of 30 [Jun 9 14:08:06] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:06] VERBOSE[23613] logger.c: Looking for 402 in flex-14 (domain pbx.example.net) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: This channel will not be able to handle video. [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: build_route: Contact hop: ;flow-id=1 [Jun 9 14:08:06] VERBOSE[23613] logger.c: list_route: hop: [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: SIP/401-08822630: New call is still down.... Trying... [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- Transmitting (no NAT) to 192.168.161.250:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-9cu0tf8ogg2b;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:06] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08822630 [Jun 9 14:08:06] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08822630 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08822630 [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Set' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [402@flex-14:1] Set("SIP/401-08822630", "ARRAY(_EXTTYPE|_STARTTIME)=flex,1213013286.455547") in new stack [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array (_EXTTYPE|_STARTTIME=flex,1213013286.455547) [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array set value (_EXTTYPE=flex) [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array set value (_STARTTIME=1213013286.455547) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/401-08822630 - state 4 (Invalid) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/401-08822630' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Expression result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'GotoIf' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [402@flex-14:2] GotoIf("SIP/401-08822630", "0?INBOUND:OUTBOUND") in new stack [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Goto (flex-14,402,8) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '401' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Macro' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [402@flex-14:8] Macro("SIP/401-08822630", "flexext|SETEXT|401") in new stack [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Goto' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:1] Goto("SIP/401-08822630", "SETEXT") in new stack [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Goto (macro-flexext,s,60) [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: Goto [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'NoOp' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:60] NoOp("SIP/401-08822630", ".... Request to set the CallerID & Context for call from flex working enabled extension: 401 ....") in new stack [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: NoOp [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Expression result is '1' [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '2' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '1.000000' [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is 'SIP/401' [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '-1.000000' [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is 'SIP/401' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Set' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:61] Set("SIP/401-08822630", "FLEXDEVICE=SIP/401") in new stack [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: Set [Jun 9 14:08:06] VERBOSE[24775] logger.c: > Found no rows [SELECT nr,name,usercontext FROM viewextensiondata WHERE devicename = 'SIP/401' AND type = 'flex'] [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Set' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:62] Set("SIP/401-08822630", "ARRAY(FLEXEXT|FLEXNAME|FLEXCONTEXT)=") in new stack [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array (FLEXEXT|FLEXNAME|FLEXCONTEXT=) [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array set value (FLEXEXT=(null)) [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array set value (FLEXNAME=(null)) [Jun 9 14:08:06] DEBUG[24775] func_strings.c: array set value (FLEXCONTEXT=(null)) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: Set [Jun 9 14:08:06] DEBUG[24775] pbx.c: Expression result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'GotoIf' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:63] GotoIf("SIP/401-08822630", "0?LOGGEDIN") in new stack [Jun 9 14:08:06] DEBUG[24775] pbx.c: Not taking any branch [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: GotoIf [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Set' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:64] Set("SIP/401-08822630", "FLEXCONTEXT=user-14") in new stack [Jun 9 14:08:06] DEBUG[24775] app_macro.c: Executed application: Set [Jun 9 14:08:06] DEBUG[24775] pbx.c: Function result is '0' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Expression result is '1' [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'ExecIf' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [s@macro-flexext:65] ExecIf("SIP/401-08822630", "1|MacroExit|") in new stack [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Goto' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [402@flex-14:9] Goto("SIP/401-08822630", "user-14|402|1") in new stack [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Goto (user-14,402,1) [Jun 9 14:08:06] DEBUG[24775] pbx.c: Launching 'Dial' [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Executing [402@user-14:1] Dial("SIP/401-08822630", "SIP/402") in new stack [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Setting NAT on RTP to Off [Jun 9 14:08:06] DEBUG[24775] acl.c: ##### Testing 192.168.161.249 with 192.168.161.0 [Jun 9 14:08:06] DEBUG[24775] acl.c: ##### Testing 192.168.161.249 with 192.168.200.0 [Jun 9 14:08:06] DEBUG[24775] acl.c: ##### Testing 192.168.161.249 with 192.168.1.0 [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: This channel will not be able to handle video. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable MACRO_DEPTH. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable FLEXCONTEXT. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable FLEXNAME. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable FLEXEXT. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable FLEXDEVICE. [Jun 9 14:08:06] DEBUG[24775] channel.c: Copying soft-transferable variable STARTTIME. [Jun 9 14:08:06] DEBUG[24775] channel.c: Copying soft-transferable variable EXTTYPE. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable SIPCALLID. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable SIPUSERAGENT. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable SIPDOMAIN. [Jun 9 14:08:06] DEBUG[24775] channel.c: Not copying variable SIPURI. [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Outgoing Call for 402 [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Updating call counter for outgoing call [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Call to peer '402' is 1 out of 30 [Jun 9 14:08:06] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/402 [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 9 14:08:06] VERBOSE[24775] logger.c: Audio is at 192.168.161.100 port 12050 [Jun 9 14:08:06] VERBOSE[24775] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:06] VERBOSE[24775] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:06] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 0: INVITE sip:402@192.168.161.249:5060 SIP/2.0 (43) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport (66) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 2: From: "Toestel 401" ;tag=as15792b4b (60) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 3: To: (34) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 4: Contact: (34) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 5: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net (57) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 7: User-Agent: atCOM PBX (21) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 9: Remote-Party-ID: "Toestel 401" ;privacy=off;screen=no (78) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 10: Date: Mon, 09 Jun 2008 12:08:06 GMT (35) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 12: Supported: replaces (19) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 14: Content-Length: 246 (19) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Header 15: (0) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: o=root 23546 23546 IN IP4 192.168.161.100 (41) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: s=session (9) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: c=IN IP4 192.168.161.100 (24) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: m=audio 12050 RTP/AVP 8 101 (27) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:06] VERBOSE[24775] logger.c: Reliably Transmitting (no NAT) to 192.168.161.249:5060: INVITE sip:402@192.168.161.249:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport From: "Toestel 401" ;tag=as15792b4b To: Contact: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net CSeq: 102 INVITE User-Agent: atCOM PBX Max-Forwards: 70 Remote-Party-ID: "Toestel 401" ;privacy=off;screen=no Date: Mon, 09 Jun 2008 12:08:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23546 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 12050 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 9 14:08:06] DEBUG[24775] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- Called 402 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/402 - state 6 (Ringing) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/402' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.249:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 From: "Toestel 401" ;tag=as15792b4b To: ;tag=ye2js7anbz Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 (71) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=as15792b4b (60) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ye2js7anbz (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net (57) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 9: Content-Length: 0 (17) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: Header 10: (0) [Jun 9 14:08:06] VERBOSE[23613] logger.c: --- (10 headers 0 lines) --- [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: = Found Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag Our tag: as15792b4b [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: *** SIP TIMER: Cancelling retransmission #1051 - INVITE (got response) [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1168c0c120e973e15ab5042160515c8e@pbx.example.net' Request 102: Found [Jun 9 14:08:06] DEBUG[23613] chan_sip.c: SIP response 180 to standard invite [Jun 9 14:08:06] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/402-0882d0e0 [Jun 9 14:08:06] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/402 [Jun 9 14:08:06] VERBOSE[24775] logger.c: -- SIP/402-0882d0e0 is ringing [Jun 9 14:08:06] VERBOSE[24775] logger.c: <--- Transmitting (no NAT) to 192.168.161.250:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-9cu0tf8ogg2b;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402-0882d0e0 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 402-0882d0e0 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/402-0882d0e0 - state 4 (Invalid) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:06] DEBUG[23576] devicestate.c: Changing state for SIP/402 - state 6 (Ringing) [Jun 9 14:08:06] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:06] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/402-0882d0e0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[23615] app_queue.c: Device 'SIP/402' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:06] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.249:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 From: "Toestel 401" ;tag=as15792b4b To: ;tag=ye2js7anbz Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 (71) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=as15792b4b (60) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ye2js7anbz (49) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net (57) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 9: Content-Length: 0 (17) [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: Header 10: (0) [Jun 9 14:08:07] VERBOSE[23613] logger.c: --- (10 headers 0 lines) --- [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: = Found Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1168c0c120e973e15ab5042160515c8e@pbx.example.net' Request 102: Found [Jun 9 14:08:07] DEBUG[23613] chan_sip.c: SIP response 180 to standard invite [Jun 9 14:08:07] VERBOSE[24775] logger.c: -- SIP/402-0882d0e0 is ringing [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:07] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.249:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 From: "Toestel 401" ;tag=as15792b4b To: ;tag=ye2js7anbz Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/7.1.33 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Content-Type: application/sdp Content-Length: 224 v=0 o=root 601845466 601845467 IN IP4 192.168.161.249 s=call c=IN IP4 192.168.161.249 t=0 0 m=audio 13724 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 200 Ok (14) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK1f33ef51;rport=5060 (71) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=as15792b4b (60) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ye2js7anbz (49) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net (57) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 7: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 9: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 10: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 11: Content-Type: application/sdp (29) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 12: Content-Length: 224 (19) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 13: (0) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: o=root 601845466 601845467 IN IP4 192.168.161.249 (49) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.249 (24) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: m=audio 13724 RTP/AVP 8 101 (27) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Line: a=sendrecv (10) [Jun 9 14:08:08] VERBOSE[23613] logger.c: --- (13 headers 11 lines) --- [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: = Found Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Acked pending invite 102 [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Stopping retransmission on '1168c0c120e973e15ab5042160515c8e@pbx.example.net' of Request 102: Match Found [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: SIP response 200 to standard invite [Jun 9 14:08:08] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.249:13724 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel SIP/402-0882d0e0 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:08] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:08] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.249:13724 [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: We have an owner, now see if we need to change this call [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Updating call counter for outgoing call [Jun 9 14:08:08] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/402 [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: build_route: Contact hop: ;flow-id=1 [Jun 9 14:08:08] VERBOSE[23613] logger.c: list_route: hop: [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Strict routing enforced for session 1168c0c120e973e15ab5042160515c8e@pbx.example.net [Jun 9 14:08:08] VERBOSE[23613] logger.c: set_destination: Parsing for address/port to send to [Jun 9 14:08:08] VERBOSE[23613] logger.c: set_destination: set destination to 192.168.161.249, port 5060 [Jun 9 14:08:08] VERBOSE[23613] logger.c: Transmitting (no NAT) to 192.168.161.249:5060: ACK sip:402@192.168.161.249:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK7626f49d;rport From: "Toestel 401" ;tag=as15792b4b To: ;tag=ye2js7anbz Contact: Call-ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net CSeq: 102 ACK User-Agent: atCOM PBX Max-Forwards: 70 Remote-Party-ID: "Toestel 401" ;privacy=off;screen=no Content-Length: 0 --- [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:08] DEBUG[23576] devicestate.c: Changing state for SIP/402 - state 2 (In use) [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:08] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/402-0882d0e0 [Jun 9 14:08:08] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/402 [Jun 9 14:08:08] VERBOSE[24775] logger.c: -- SIP/402-0882d0e0 answered SIP/401-08822630 [Jun 9 14:08:08] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08822630 [Jun 9 14:08:08] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: SIP answering channel: SIP/401-08822630 [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: Setting framing from config on incoming call [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 9 14:08:08] VERBOSE[24775] logger.c: Audio is at 192.168.161.100 port 19830 [Jun 9 14:08:08] VERBOSE[24775] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:08] VERBOSE[24775] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:08] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:08] VERBOSE[24775] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.250:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-9cu0tf8ogg2b;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23546 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 19830 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 9 14:08:08] DEBUG[24775] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:08] VERBOSE[24775] logger.c: -- Packet2Packet bridging SIP/401-08822630 and SIP/402-0882d0e0 [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[23615] app_queue.c: Device 'SIP/402' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402-0882d0e0 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 402-0882d0e0 [Jun 9 14:08:08] DEBUG[23576] devicestate.c: Changing state for SIP/402-0882d0e0 - state 4 (Invalid) [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:08] DEBUG[23576] devicestate.c: Changing state for SIP/402 - state 2 (In use) [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 402 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 402 [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08822630 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08822630 [Jun 9 14:08:08] DEBUG[23615] app_queue.c: Device 'SIP/402-0882d0e0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:08] DEBUG[23615] app_queue.c: Device 'SIP/402' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:08] DEBUG[23576] devicestate.c: Changing state for SIP/401-08822630 - state 4 (Invalid) [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:08] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:08] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:08] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:08] DEBUG[23615] app_queue.c: Device 'SIP/401-08822630' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:08] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> ACK sip:402@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-bow1hj36byuu;rport From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 2 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 0: ACK sip:402@192.168.161.100 SIP/2.0 (35) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-bow1hj36byuu;rport (71) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as55064749 (55) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 5: CSeq: 2 ACK (11) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:08] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1053 [Jun 9 14:08:08] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61727a6d72-hngk6cx7x17v' of Response 2: Match Found [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:08] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:09] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] rtp.c: Ooh, format changed from unknown to alaw [Jun 9 14:08:10] DEBUG[24774] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:10] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> INVITE sip:402@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0tov15xjok9z;rport From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 3 INVITE Max-Forwards: 70 Contact: ;flow-id=1 P-Key-Flags: resolution="31x13", keys="4" User-Agent: snom360/7.1.33 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 222 v=0 o=root 84706495 84706496 IN IP4 192.168.161.250 s=call c=IN IP4 192.168.161.250 t=0 0 m=audio 18992 RTP/AVP 8 101 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendonly <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: INVITE sip:402@192.168.161.100 SIP/2.0 (38) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0tov15xjok9z;rport (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as55064749 (55) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 3 INVITE (14) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 10: Accept: application/sdp (23) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 15: Min-SE: 90 (10) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 16: Content-Type: application/sdp (29) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 17: Content-Length: 222 (19) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 18: (0) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: v=0 (3) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: o=root 84706495 84706496 IN IP4 192.168.161.250 (47) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: s=call (6) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: c=IN IP4 192.168.161.250 (24) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: t=0 0 (5) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: m=audio 18992 RTP/AVP 8 101 (27) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: a=ptime:20 (10) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Line: a=sendonly (10) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (18 headers 11 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 9 14:08:11] VERBOSE[23613] logger.c: Sending to 192.168.161.250 : 5060 (NAT) [Jun 9 14:08:11] VERBOSE[23613] logger.c: Found RTP audio format 8 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Found RTP audio format 101 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 9 14:08:11] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:18992 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Found audio description format pcma for ID 8 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Found audio description format telephone-event for ID 101 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Got unsupported a:fmtp in SDP offer [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: T38 state changed to 0 on channel SIP/401-08822630 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [Jun 9 14:08:11] VERBOSE[23613] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 9 14:08:11] VERBOSE[23613] logger.c: Peer audio RTP is at port 192.168.161.250:18992 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: We have an owner, now see if we need to change this call [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Got a SIP re-invite for call 3c61727a6d72-hngk6cx7x17v [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP/401-08822630: This call is UP.... [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0tov15xjok9z;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 3 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Setting framing from config on incoming call [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 9 14:08:11] VERBOSE[23613] logger.c: Audio is at 192.168.161.100 port 19830 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Adding codec 0x8 (alaw) to SDP [Jun 9 14:08:11] VERBOSE[23613] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- Done with adding codecs to SDP [Jun 9 14:08:11] DEBUG[23613] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=33) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- Reliably Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-0tov15xjok9z;received=192.168.161.250;rport=5060 From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 3 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 23546 23547 IN IP4 192.168.161.100 s=session c=IN IP4 192.168.161.100 t=0 0 m=audio 19830 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=recvonly <------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:11] VERBOSE[24775] logger.c: -- Started music on hold, class 'default', on SIP/402-0882d0e0 [Jun 9 14:08:11] DEBUG[24775] channel.c: Scheduling timer at 160 sample intervals [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24775] channel.c: Generator got voice, switching to phase locked mode [Jun 9 14:08:11] DEBUG[24775] channel.c: Scheduling timer at 0 sample intervals [Jun 9 14:08:11] DEBUG[24775] res_musiconhold.c: SIP/402-0882d0e0 Opened file 0 '/var/lib/asterisk/moh/default/sunshine' [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] rtp.c: Ooh, format changed from unknown to alaw [Jun 9 14:08:11] DEBUG[24775] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] DEBUG[24775] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37) [Jun 9 14:08:11] DEBUG[24774] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> REFER sip:400@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-24dwyr2wo5ox;rport From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 2 REFER Max-Forwards: 70 Contact: ;flow-id=1 Refer-To: sip:402@192.168.161.100?Replaces=3c61727a6d72-hngk6cx7x17v%3Bto-tag%3Das55064749%3Bfrom-tag%3D4xerru1alm Referred-By: sip:401@pbx.example.net User-Agent: snom360/7.1.33 Content-Length: 0 <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: REFER sip:400@192.168.161.100 SIP/2.0 (37) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-24dwyr2wo5ox;rport (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=ldxuvi1dse (51) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: "Toestel 400" ;tag=as3c18a7ab (58) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 2 REFER (13) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: Refer-To: sip:402@192.168.161.100?Replaces=3c61727a6d72-hngk6cx7x17v%3Bto-tag%3Das55064749%3Bfrom-tag%3D4xerru1alm (114) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 9: Referred-By: sip:401@pbx.example.net (36) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 10: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 12: (0) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (12 headers 0 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jun 9 14:08:11] VERBOSE[23613] logger.c: Call 194a081732806989569ccf6c70db082b@pbx.example.net got a SIP call transfer from caller: (REFER)! [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Attended transfer: Will use Replace-Call-ID : 3c61727a6d72-hngk6cx7x17v (No check of from/to tags) [Jun 9 14:08:11] VERBOSE[23613] logger.c: SIP transfer to extension 402@flex-14 by 401@pbx.example.net [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP attended transfer: Transferer channel SIP/401-08820780, transferee channel SIP/400-08825f48 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Got SIP transfer, applying to bridged peer 'SIP/400-08825f48' [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Looking for callid 3c61727a6d72-hngk6cx7x17v (fromtag 4xerru1alm totag as55064749) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Matched INCOMING call - their tag is 4xerru1alm Our tag is as55064749 [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-24dwyr2wo5ox;received=192.168.161.250;rport=5060 From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 2 REFER User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP attended transfer: trying to bridge SIP/401-08822630 and SIP/400-08825f48 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Sip transfer:-------------------- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- Transferer to PBX channel: SIP/401-08820780 State Up [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- Transferer to PBX second channel (target): SIP/401-08822630 State Up [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- Bridged call to transferee: SIP/400-08825f48 State Up [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- Bridged call to transfer target: SIP/402-0882d0e0 State Up [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: -- END Sip transfer:-------------------- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP transfer: Four channels to handle [Jun 9 14:08:11] VERBOSE[23613] logger.c: -- Stopped music on hold on SIP/400-08825f48 [Jun 9 14:08:11] DEBUG[23613] channel.c: Scheduling timer at 0 sample intervals [Jun 9 14:08:11] VERBOSE[23613] logger.c: -- Stopped music on hold on SIP/402-0882d0e0 [Jun 9 14:08:11] DEBUG[23613] channel.c: Scheduling timer at 0 sample intervals [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP transfer: trying to masquerade SIP/400-08825f48 into SIP/401-08822630 [Jun 9 14:08:11] DEBUG[23613] channel.c: Planning to masquerade channel SIP/400-08825f48 into the structure of SIP/401-08822630 [Jun 9 14:08:11] DEBUG[23613] channel.c: Done planning to masquerade channel SIP/400-08825f48 into the structure of SIP/401-08822630 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP transfer: Succeeded to masquerade channels. [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Strict routing enforced for session 194a081732806989569ccf6c70db082b@pbx.example.net [Jun 9 14:08:11] VERBOSE[23613] logger.c: set_destination: Parsing for address/port to send to [Jun 9 14:08:11] VERBOSE[23613] logger.c: set_destination: set destination to 192.168.161.250, port 5060 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Reliably Transmitting (NAT) to 192.168.161.250:5060: NOTIFY sip:401@192.168.161.250:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6c4af2b2;rport From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Contact: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 103 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Remote-Party-ID: "Toestel 400" ;privacy=off;screen=no Event: refer;id=2 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 OK --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: SIP attended transfer: Unlocking channel SIP/401-08822630 [Jun 9 14:08:11] DEBUG[24774] rtp.c: Oooh, something is weird, backing out [Jun 9 14:08:11] DEBUG[24775] channel.c: Actually Masquerading SIP/400-08825f48(6) into the structure of SIP/401-08822630(6) [Jun 9 14:08:11] DEBUG[24775] channel.c: Got clone lock for masquerade on 'SIP/400-08825f48' at 0x88ef838 [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: SIP Fixup: New owner for dialogue 3c61727a6d72-hngk6cx7x17v: SIP/400-08825f48 (Old parent: SIP/400-08825f48) [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: Hangup call SIP/400-08825f48, SIP callid 3c61727a6d72-hngk6cx7x17v) [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: update_call_counter(401) - decrement call limit counter on hangup [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: Updating call counter for incoming call [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: Call from peer '401' removed from call limit 30 [Jun 9 14:08:11] DEBUG[24775] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:11] VERBOSE[24775] logger.c: Scheduling destruction of SIP dialog '3c61727a6d72-hngk6cx7x17v' in 32000 ms (Method: INVITE) [Jun 9 14:08:11] DEBUG[24775] channel.c: Putting channel SIP/400-08825f48 in 8/8 formats [Jun 9 14:08:11] DEBUG[24775] chan_sip.c: SIP Fixup: New owner for dialogue 3c61723dbade-gpgrmqxnpa8h: SIP/400-08825f48 (Old parent: SIP/401-08822630) [Jun 9 14:08:11] DEBUG[24775] channel.c: Released clone lock on 'SIP/401-08822630' [Jun 9 14:08:11] DEBUG[24775] channel.c: Done Masquerading SIP/400-08825f48 (6) [Jun 9 14:08:11] DEBUG[24775] rtp.c: Oooh, something is weird, backing out [Jun 9 14:08:11] VERBOSE[24775] logger.c: -- Packet2Packet bridging SIP/400-08825f48 and SIP/402-0882d0e0 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 2 (In use) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[24774] channel.c: Didn't get a frame from channel: SIP/401-08822630 [Jun 9 14:08:11] DEBUG[24774] channel.c: Bridge stops bridging channels SIP/401-08822630 and SIP/401-08820780 [Jun 9 14:08:11] DEBUG[24774] channel.c: Hanging up channel 'SIP/401-08820780' [Jun 9 14:08:11] DEBUG[24774] chan_sip.c: update_call_counter(401) - decrement call limit counter on hangup [Jun 9 14:08:11] DEBUG[24774] chan_sip.c: Updating call counter for outgoing call [Jun 9 14:08:11] DEBUG[24774] chan_sip.c: Call to peer '401' removed from call limit 30 [Jun 9 14:08:11] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:11] DEBUG[24774] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 194a081732806989569ccf6c70db082b@pbx.example.net. [Jun 9 14:08:11] VERBOSE[24774] logger.c: Scheduling destruction of SIP dialog '194a081732806989569ccf6c70db082b@pbx.example.net' in 32000 ms (Method: REFER) [Jun 9 14:08:11] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08820780 [Jun 9 14:08:11] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:11] DEBUG[24774] rtp.c: Channel '' has no RTP, not doing anything [Jun 9 14:08:11] DEBUG[24774] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 9 14:08:11] DEBUG[24774] pbx.c: Spawn extension (user-01,401,1) exited non-zero on 'SIP/401-08822630' [Jun 9 14:08:11] VERBOSE[24774] logger.c: == Spawn extension (user-01, 401, 1) exited non-zero on 'SIP/401-08822630' [Jun 9 14:08:11] DEBUG[24774] channel.c: Soft-Hanging up channel 'SIP/401-08822630' [Jun 9 14:08:11] DEBUG[24774] pbx.c: Launching 'Hangup' [Jun 9 14:08:11] VERBOSE[24774] logger.c: -- Executing [h@user-01:1] Hangup("SIP/401-08822630", "") in new stack [Jun 9 14:08:11] DEBUG[24774] pbx.c: Spawn extension (user-01,h,1) exited non-zero on 'SIP/401-08822630' [Jun 9 14:08:11] VERBOSE[24774] logger.c: == Spawn extension (user-01, h, 1) exited non-zero on 'SIP/401-08822630' [Jun 9 14:08:11] DEBUG[24774] channel.c: Hanging up zombie 'SIP/401-08822630' [Jun 9 14:08:11] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401-08822630 [Jun 9 14:08:11] DEBUG[24774] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:11] DEBUG[24774] cdr.c: Dropping CDR ! [Jun 9 14:08:11] NOTICE[24774] cdr.c: CDR on channel 'SIP/401-08820780' not posted [Jun 9 14:08:11] NOTICE[24774] cdr.c: CDR on channel 'SIP/400-08825f48' not posted [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 1 (Not in use) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08820780 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08820780 [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401-08820780 - state 4 (Invalid) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 1 (Not in use) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401-08822630 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401-08822630 [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401-08820780' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401-08822630 - state 4 (Invalid) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 1 (Not in use) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401-08822630' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> ACK sip:402@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-mgzz09ckmlfo;rport From: "Toestel 401" ;tag=4xerru1alm To: ;tag=as55064749 Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 3 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: ACK sip:402@192.168.161.100 SIP/2.0 (35) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-mgzz09ckmlfo;rport (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 401" ;tag=4xerru1alm (60) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=as55064749 (55) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 3 ACK (11) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: Content-Length: 0 (17) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 9: (0) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (9 headers 0 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1055 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61727a6d72-hngk6cx7x17v' of Response 3: Match Found [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Strict routing enforced for session 3c61727a6d72-hngk6cx7x17v [Jun 9 14:08:11] VERBOSE[23613] logger.c: set_destination: Parsing for address/port to send to [Jun 9 14:08:11] VERBOSE[23613] logger.c: set_destination: set destination to 192.168.161.250, port 5060 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Reliably Transmitting (NAT) to 192.168.161.250:5060: BYE sip:401@192.168.161.250:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6a992105;rport From: ;tag=as55064749 To: "Toestel 401" ;tag=4xerru1alm Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 102 BYE User-Agent: atCOM PBX Max-Forwards: 70 Content-Length: 0 --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Jun 9 14:08:11] VERBOSE[23613] logger.c: Scheduling destruction of SIP dialog '3c61727a6d72-hngk6cx7x17v' in 32000 ms (Method: ACK) [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6c4af2b2;rport=5060 From: "Toestel 400" ;tag=as3c18a7ab To: ;tag=ldxuvi1dse Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 103 NOTIFY Contact: ;flow-id=1 Content-Length: 0 <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 200 Ok (14) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6c4af2b2;rport=5060 (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: "Toestel 400" ;tag=as3c18a7ab (60) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: ;tag=ldxuvi1dse (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 103 NOTIFY (16) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: Content-Length: 0 (17) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: (0) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (8 headers 0 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1057 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Stopping retransmission on '194a081732806989569ccf6c70db082b@pbx.example.net' of Request 103: Match Found [Jun 9 14:08:11] VERBOSE[23613] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> BYE sip:400@192.168.161.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-qcreg0xjoazn;rport From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 3 BYE Max-Forwards: 70 Contact: ;flow-id=1 User-Agent: snom360/7.1.33 RTP-RxStat: Total_Rx_Pkts=124,Rx_Pkts=0,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=125,Tx_Pkts=0,Remote_Tx_Pkts=0 Content-Length: 0 <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: BYE sip:400@192.168.161.100 SIP/2.0 (35) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-qcreg0xjoazn;rport (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=ldxuvi1dse (51) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: "Toestel 400" ;tag=as3c18a7ab (58) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net (57) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 3 BYE (11) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Max-Forwards: 70 (16) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 9: RTP-RxStat: Total_Rx_Pkts=124,Rx_Pkts=0,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (76) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 10: RTP-TxStat: Total_Tx_Pkts=125,Tx_Pkts=0,Remote_Tx_Pkts=0 (56) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 11: Content-Length: 0 (17) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 12: (0) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (12 headers 0 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 9 14:08:11] VERBOSE[23613] logger.c: Sending to 192.168.161.250 : 5060 (NAT) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Setting SIP_ALREADYGONE on dialog 194a081732806989569ccf6c70db082b@pbx.example.net [Jun 9 14:08:11] VERBOSE[23613] logger.c: Scheduling destruction of SIP dialog '194a081732806989569ccf6c70db082b@pbx.example.net' in 32000 ms (Method: BYE) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Received bye, no owner, selfdestruct soon. [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- Transmitting (NAT) to 192.168.161.250:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-qcreg0xjoazn;received=192.168.161.250;rport=5060 From: ;tag=ldxuvi1dse To: "Toestel 400" ;tag=as3c18a7ab Call-ID: 194a081732806989569ccf6c70db082b@pbx.example.net CSeq: 3 BYE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:11] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.250:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6a992105;rport=5060 From: ;tag=as55064749 To: "Toestel 401" ;tag=4xerru1alm Call-ID: 3c61727a6d72-hngk6cx7x17v CSeq: 102 BYE Contact: ;flow-id=1 User-Agent: snom360/7.1.33 RTP-RxStat: Total_Rx_Pkts=135,Rx_Pkts=0,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=141,Tx_Pkts=0,Remote_Tx_Pkts=0 Content-Length: 0 <-------------> [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6a992105;rport=5060 (71) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 2: From: ;tag=as55064749 (57) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 3: To: "Toestel 401" ;tag=4xerru1alm (58) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 4: Call-ID: 3c61727a6d72-hngk6cx7x17v (34) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 5: CSeq: 102 BYE (13) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 6: Contact: ;flow-id=1 (49) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 7: User-Agent: snom360/7.1.33 (26) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 8: RTP-RxStat: Total_Rx_Pkts=135,Rx_Pkts=0,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (76) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 9: RTP-TxStat: Total_Tx_Pkts=141,Tx_Pkts=0,Remote_Tx_Pkts=0 (56) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 10: Content-Length: 0 (17) [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Header 11: (0) [Jun 9 14:08:11] VERBOSE[23613] logger.c: --- (11 headers 0 lines) --- [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: = Found Their Call ID: 3c61727a6d72-hngk6cx7x17v Their Tag 4xerru1alm Our tag: as55064749 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1060 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Stopping retransmission on '3c61727a6d72-hngk6cx7x17v' of Request 102: Match Found [Jun 9 14:08:11] VERBOSE[23613] logger.c: SIP Response message for INCOMING dialog BYE arrived [Jun 9 14:08:11] VERBOSE[23613] logger.c: Really destroying SIP dialog '3c61727a6d72-hngk6cx7x17v' Method: ACK [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Updating call counter for incoming call [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: Call from peer '401' removed from call limit 30 [Jun 9 14:08:11] DEBUG[23613] devicestate.c: Notification of state change to be queued on device/channel SIP/401 [Jun 9 14:08:11] DEBUG[23613] chan_sip.c: This call did not properly clean up call limits. Call ID 3c61727a6d72-hngk6cx7x17v [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23576] devicestate.c: Changing state for SIP/401 - state 1 (Not in use) [Jun 9 14:08:11] DEBUG[23576] devicestate.c: No provider found, checking channel drivers for SIP - 401 [Jun 9 14:08:11] DEBUG[23576] chan_sip.c: Checking device state for peer 401 [Jun 9 14:08:11] DEBUG[23615] app_queue.c: Device 'SIP/401' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 9 14:08:16] VERBOSE[23613] logger.c: <--- SIP read from 192.168.161.237:5060 ---> REGISTER sip:pbx.example.net SIP/2.0 Via: SIP/2.0/UDP 192.168.161.237;branch=z9hG4bKac1051566486 Max-Forwards: 70 From: ;tag=1c1051563159 To: Call-ID: 4743305952942008195958@192.168.161.237 CSeq: 78232 REGISTER Contact: ;expires=180 Supported: em,timer,replaces,path,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Expires: 180 User-Agent: acMP114-01/v.5.20A.032.001 Content-Length: 0 <-------------> [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.237;branch=z9hG4bKac1051566486 (59) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 2: Max-Forwards: 70 (16) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 3: From: ;tag=1c1051563159 (48) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 4: To: (29) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 5: Call-ID: 4743305952942008195958@192.168.161.237 (47) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 6: CSeq: 78232 REGISTER (20) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 7: Contact: ;expires=180 (46) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 8: Supported: em,timer,replaces,path,resource-priority (51) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 9: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 10: Expires: 180 (12) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 11: User-Agent: acMP114-01/v.5.20A.032.001 (38) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 12: Content-Length: 0 (17) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Header 13: (0) [Jun 9 14:08:16] VERBOSE[23613] logger.c: --- (13 headers 0 lines) --- [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 1168c0c120e973e15ab5042160515c8e@pbx.example.net Their Tag ye2js7anbz Our tag: as15792b4b [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 194a081732806989569ccf6c70db082b@pbx.example.net Their Tag ldxuvi1dse Our tag: as3c18a7ab [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c61723dbade-gpgrmqxnpa8h Their Tag vpiiod4wrz Our tag: as5d44649b [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 13af400-0-13c4-2c39e-2c5c225e-2c39e Their Tag 13a0260-0-13c4-2c39e-620846bf-2c39e Our tag: as11a0a34d [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26702775b0-f459rxlh8554 Their Tag vpwde33r8q Our tag: as5c719ba7 [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad395-ajo6vj1qc0vm Their Tag 97qngh5alh Our tag: as39395c26 [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad4c6-phe3ytd26k13 Their Tag hf67o5uhr4 Our tag: as73260cbd [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad52a-gwy8p5tlpim3 Their Tag sjongh64mn Our tag: as56f28897 [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: = No match Their Call ID: 3c26701ad45e-7fxbtgnl1u8t Their Tag tstmut2dxd Our tag: as602e2d77 [Jun 9 14:08:16] DEBUG[23613] acl.c: ##### Testing 192.168.161.237 with 192.168.161.0 [Jun 9 14:08:16] DEBUG[23613] acl.c: ##### Testing 192.168.161.237 with 192.168.200.0 [Jun 9 14:08:16] DEBUG[23613] acl.c: ##### Testing 192.168.161.237 with 192.168.1.0 [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: Allocating new SIP dialog for 4743305952942008195958@192.168.161.237 - REGISTER (No RTP) [Jun 9 14:08:16] DEBUG[23613] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 9 14:08:16] VERBOSE[23613] logger.c: Using latest REGISTER request as basis request [Jun 9 14:08:16] VERBOSE[23613] logger.c: Sending to 192.168.161.237 : 5060 (no NAT) [Jun 9 14:08:16] VERBOSE[23613] logger.c: <--- Transmitting (no NAT) to 192.168.161.237:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.237;branch=z9hG4bKac1051566486;received=192.168.161.237 From: ;tag=1c1051563159 To: Call-ID: 4743305952942008195958@192.168.161.237 CSeq: 78232 REGISTER User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jun 9 14:08:16] VERBOSE[23613] logger.c: <--- Transmitting (no NAT) to 192.168.161.237:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.161.237;branch=z9hG4bKac1051566486;received=192.168.161.237 From: ;tag=1c1051563159 To: ;tag=as7dd98d8d Call-ID: 4743305952942008195958@192.168.161.237 CSeq: 78232 REGISTER User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="siprealm", nonce="6c6f23af" Content-Length: 0 <------------> [Jun 9 14:08:16] VERBOSE[23613] logger.c: Scheduling destruction of SIP dialog '4743305952942008195958@192.168.161.237' in 32000 ms (Method: REGISTER) [Jun 9 14:08:16] DEBUG[24803] manager.c: Manager received command 'login' [Jun 9 14:08:16] VERBOSE[24803] logger.c: == Parsing '/etc/asterisk/manager.conf': [Jun 9 14:08:16] DEBUG[24803] config.c: Parsing /etc/asterisk/manager.conf [Jun 9 14:08:16] VERBOSE[24803] logger.c: Found [Jun 9 14:08:16] VERBOSE[24803] logger.c: == Parsing '/etc/asterisk/settings/manager.conf': [Jun 9 14:08:16] DEBUG[24803] config.c: Parsing /etc/asterisk/settings/manager.conf [Jun 9 14:08:16] VERBOSE[24803] logger.c: Found [Jun 9 14:08:16] DEBUG[24803] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer [Jun 9 14:08:16] DEBUG[24803] acl.c: 127.0.0.1/255.255.255.255/255.255.255.255 appended to acl for peer [Jun 9 14:08:16] DEBUG[24803] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 [Jun 9 14:08:16] DEBUG[24803] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1 [Jun 9 14:08:16] VERBOSE[24803] logger.c: == Manager 'lmt' logged on from 127.0.0.1 [Jun 9 14:08:16] DEBUG[24803] manager.c: Manager received command 'Command'