[May 29 09:06:42] VERBOSE[14297] logger.c: <--- SIP read from 192.168.161.233:5060 ---> INVITE sip:422@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-npktsxaogdnn;rport From: "Theo 3" ;tag=iaql6jp6c9 To: Call-ID: 3c275dba4a85-2z7732ti3iws 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: 248 v=0 o=root 375022119 375022119 IN IP4 192.168.161.233 s=call c=IN IP4 192.168.161.233 t=0 0 m=audio 10396 RTP/AVP 9 8 101 a=rtpmap:9 g722/8000 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 0: INVITE sip:422@pbx.example.net;user=phone SIP/2.0 (49) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-npktsxaogdnn;rport (71) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 2: From: "Theo 3" ;tag=iaql6jp6c9 (55) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 3: To: (40) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 4: Call-ID: 3c275dba4a85-2z7732ti3iws (34) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 5: CSeq: 1 INVITE (14) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 10: Accept: application/sdp (23) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 15: Min-SE: 90 (10) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 16: Content-Type: application/sdp (29) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 17: Content-Length: 248 (19) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Header 18: (0) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: v=0 (3) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: o=root 375022119 375022119 IN IP4 192.168.161.233 (49) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: s=call (6) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: c=IN IP4 192.168.161.233 (24) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: t=0 0 (5) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: m=audio 10396 RTP/AVP 9 8 101 (29) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=rtpmap:9 g722/8000 (20) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=ptime:20 (10) [May 29 09:06:42] DEBUG[14297] chan_sip.c: Line: a=sendrecv (10) [May 29 09:06:42] VERBOSE[14297] logger.c: --- (18 headers 12 lines) --- [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 4743299462942008195958@192.168.161.237 Their Tag 1c20012293 Our tag: as67dbd79a [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 4743318622942008195958@192.168.161.237 Their Tag 1c19984601 Our tag: as3d030876 [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 4743312262942008195958@192.168.161.237 Their Tag 1c19965716 Our tag: as0891d0bc [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 4743305952942008195958@192.168.161.237 Their Tag 1c19904868 Our tag: as0b774729 [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 5d9f84361eecc1110f4079100cffc372@pbx.example.net Their Tag Our tag: as7d4ef13d [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 3c275da4bc9c-ifp60or5zdv8 Their Tag zmb78yuckm Our tag: as03e492b1 [May 29 09:06:42] DEBUG[14297] chan_sip.c: = No match Their Call ID: 3c4ec3d18375-5g0qig1j5dob Their Tag rmfjphr70f Our tag: as339e6b66 [May 29 09:06:42] DEBUG[14297] acl.c: ##### Testing 192.168.161.233 with 192.168.161.0 [May 29 09:06:42] DEBUG[14297] acl.c: ##### Testing 192.168.161.233 with 192.168.200.0 [May 29 09:06:42] DEBUG[14297] acl.c: ##### Testing 192.168.161.233 with 192.168.1.0 [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on RTP to Off [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on VRTP to Off [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on UDPTL to Off [May 29 09:06:42] DEBUG[14297] chan_sip.c: Allocating new SIP dialog for 3c275dba4a85-2z7732ti3iws - INVITE (With RTP) [May 29 09:06:42] DEBUG[14297] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 29 09:06:42] DEBUG[14297] chan_sip.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [May 29 09:06:42] DEBUG[14297] chan_sip.c: Found SIP option: -timer- [May 29 09:06:42] DEBUG[14297] chan_sip.c: Matched SIP option: timer [May 29 09:06:42] DEBUG[14297] chan_sip.c: Found SIP option: -100rel- [May 29 09:06:42] DEBUG[14297] chan_sip.c: Matched SIP option: 100rel [May 29 09:06:42] DEBUG[14297] chan_sip.c: Found SIP option: -replaces- [May 29 09:06:42] DEBUG[14297] chan_sip.c: Matched SIP option: replaces [May 29 09:06:42] DEBUG[14297] chan_sip.c: Found SIP option: -from-change- [May 29 09:06:42] DEBUG[14297] chan_sip.c: Found no match for SIP option: from-change (Please file bug report!) [May 29 09:06:42] VERBOSE[14297] logger.c: Sending to 192.168.161.233 : 5060 (NAT) [May 29 09:06:42] VERBOSE[14297] logger.c: Using INVITE request as basis request - 3c275dba4a85-2z7732ti3iws [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on RTP to Off [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on VRTP to Off [May 29 09:06:42] DEBUG[14297] chan_sip.c: Setting NAT on UDPTL to Off [May 29 09:06:42] VERBOSE[14297] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.233:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-npktsxaogdnn;received=192.168.161.233;rport=5060 From: "Theo 3" ;tag=iaql6jp6c9 To: ;tag=as44691745 Call-ID: 3c275dba4a85-2z7732ti3iws 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="4daaec93" Content-Length: 0 <------------> [May 29 09:06:42] DEBUG[14297] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 29 09:06:42] VERBOSE[14297] logger.c: Scheduling destruction of SIP dialog '3c275dba4a85-2z7732ti3iws' in 32000 ms (Method: INVITE) [May 29 09:06:42] VERBOSE[14297] logger.c: Found user '421' [May 29 09:06:43] VERBOSE[14297] logger.c: <--- SIP read from 192.168.161.233:5060 ---> ACK sip:422@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-npktsxaogdnn;rport From: "Theo 3" ;tag=iaql6jp6c9 To: ;tag=as44691745 Call-ID: 3c275dba4a85-2z7732ti3iws CSeq: 1 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 0: ACK sip:422@pbx.example.net;user=phone SIP/2.0 (46) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-npktsxaogdnn;rport (71) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 2: From: "Theo 3" ;tag=iaql6jp6c9 (55) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 3: To: ;tag=as44691745 (55) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 4: Call-ID: 3c275dba4a85-2z7732ti3iws (34) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 5: CSeq: 1 ACK (11) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 8: Content-Length: 0 (17) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 9: (0) [May 29 09:06:43] VERBOSE[14297] logger.c: --- (9 headers 0 lines) --- [May 29 09:06:43] DEBUG[14297] chan_sip.c: = Found Their Call ID: 3c275dba4a85-2z7732ti3iws Their Tag iaql6jp6c9 Our tag: as44691745 [May 29 09:06:43] DEBUG[14297] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 29 09:06:43] DEBUG[14297] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1598 [May 29 09:06:43] DEBUG[14297] chan_sip.c: Stopping retransmission on '3c275dba4a85-2z7732ti3iws' of Response 1: Match Found [May 29 09:06:43] VERBOSE[14297] logger.c: <--- SIP read from 192.168.161.233:5060 ---> INVITE sip:422@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;rport From: "Theo 3" ;tag=iaql6jp6c9 To: Call-ID: 3c275dba4a85-2z7732ti3iws 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="421",realm="siprealm",nonce="4daaec93",uri="sip:422@pbx.example.net;user=phone",response="d352d0048e2562d7c6a7ba87d076f3f9",algorithm=MD5 Content-Type: application/sdp Content-Length: 248 v=0 o=root 375022119 375022119 IN IP4 192.168.161.233 s=call c=IN IP4 192.168.161.233 t=0 0 m=audio 10396 RTP/AVP 9 8 101 a=rtpmap:9 g722/8000 a=rtpmap:8 pcma/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 0: INVITE sip:422@pbx.example.net;user=phone SIP/2.0 (49) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;rport (71) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 2: From: "Theo 3" ;tag=iaql6jp6c9 (55) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 3: To: (40) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 4: Call-ID: 3c275dba4a85-2z7732ti3iws (34) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 8: P-Key-Flags: resolution="31x13", keys="4" (41) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 9: User-Agent: snom360/7.1.33 (26) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 10: Accept: application/sdp (23) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 15: Min-SE: 90 (10) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 16: Proxy-Authorization: Digest username="421",realm="siprealm",nonce="4daaec93",uri="sip:422@pbx.example.net;user=phone",response="d352d0048e2562d7c6a7ba87d076f3f9",algorithm=MD5 (175) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 17: Content-Type: application/sdp (29) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 18: Content-Length: 248 (19) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 19: (0) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: v=0 (3) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: o=root 375022119 375022119 IN IP4 192.168.161.233 (49) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: s=call (6) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: c=IN IP4 192.168.161.233 (24) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: t=0 0 (5) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: m=audio 10396 RTP/AVP 9 8 101 (29) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=rtpmap:9 g722/8000 (20) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=ptime:20 (10) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Line: a=sendrecv (10) [May 29 09:06:43] VERBOSE[14297] logger.c: --- (19 headers 12 lines) --- [May 29 09:06:43] DEBUG[14297] chan_sip.c: = Found Their Call ID: 3c275dba4a85-2z7732ti3iws Their Tag iaql6jp6c9 Our tag: as44691745 [May 29 09:06:43] DEBUG[14297] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 29 09:06:43] VERBOSE[14297] logger.c: Sending to 192.168.161.233 : 5060 (NAT) [May 29 09:06:43] VERBOSE[14297] logger.c: Using INVITE request as basis request - 3c275dba4a85-2z7732ti3iws [May 29 09:06:43] DEBUG[14297] chan_sip.c: Setting NAT on RTP to Off [May 29 09:06:43] DEBUG[14297] chan_sip.c: Setting NAT on VRTP to Off [May 29 09:06:43] DEBUG[14297] chan_sip.c: Setting NAT on UDPTL to Off [May 29 09:06:43] VERBOSE[14297] logger.c: Found user '421' [May 29 09:06:43] VERBOSE[14297] logger.c: Found RTP audio format 9 [May 29 09:06:43] VERBOSE[14297] logger.c: Found RTP audio format 8 [May 29 09:06:43] VERBOSE[14297] logger.c: Found RTP audio format 101 [May 29 09:06:43] DEBUG[14297] chan_sip.c: Peer doesn't provide T.38 UDPTL [May 29 09:06:43] VERBOSE[14297] logger.c: Peer audio RTP is at port 192.168.161.233:10396 [May 29 09:06:43] VERBOSE[14297] logger.c: Found audio description format g722 for ID 9 [May 29 09:06:43] VERBOSE[14297] logger.c: Found audio description format pcma for ID 8 [May 29 09:06:43] VERBOSE[14297] logger.c: Found audio description format telephone-event for ID 101 [May 29 09:06:43] VERBOSE[14297] logger.c: Got unsupported a:fmtp in SDP offer [May 29 09:06:43] DEBUG[14297] chan_sip.c: T38 state changed to 0 on channel [May 29 09:06:43] VERBOSE[14297] logger.c: Capabilities: us - 0x1008 (alaw|g722), peer - audio=0x1008 (alaw|g722)/video=0x0 (nothing), combined - 0x1008 (alaw|g722) [May 29 09:06:43] VERBOSE[14297] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 29 09:06:43] VERBOSE[14297] logger.c: Peer audio RTP is at port 192.168.161.233:10396 [May 29 09:06:43] DEBUG[14297] chan_sip.c: We're settling with these formats: 0x1008 (alaw|g722) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Checking SIP call limits for device 421 [May 29 09:06:43] DEBUG[14297] chan_sip.c: Updating call counter for incoming call [May 29 09:06:43] DEBUG[14297] chan_sip.c: Call from peer '421' is 1 out of 30 [May 29 09:06:43] DEBUG[14297] devicestate.c: Notification of state change to be queued on device/channel SIP/421 [May 29 09:06:43] VERBOSE[14297] logger.c: Looking for 422 in user-01 (domain pbx.example.net) [May 29 09:06:43] DEBUG[14297] chan_sip.c: *** Our native formats are 0x1000 (g722) [May 29 09:06:43] DEBUG[14297] chan_sip.c: *** Joint capabilities are 0x1008 (alaw|g722) [May 29 09:06:43] DEBUG[14297] chan_sip.c: *** Our capabilities are 0x1008 (alaw|g722) [May 29 09:06:43] DEBUG[14297] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [May 29 09:06:43] DEBUG[14297] chan_sip.c: This channel will not be able to handle video. [May 29 09:06:43] DEBUG[14297] chan_sip.c: build_route: Contact hop: ;flow-id=1 [May 29 09:06:43] VERBOSE[14297] logger.c: list_route: hop: [May 29 09:06:43] DEBUG[14297] chan_sip.c: SIP/421-0a0f4860: New call is still down.... Trying... [May 29 09:06:43] VERBOSE[14297] logger.c: <--- Transmitting (no NAT) to 192.168.161.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;received=192.168.161.233;rport=5060 From: "Theo 3" ;tag=iaql6jp6c9 To: Call-ID: 3c275dba4a85-2z7732ti3iws CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 29 09:06:43] DEBUG[14297] devicestate.c: Notification of state change to be queued on device/channel SIP/421-0a0f4860 [May 29 09:06:43] DEBUG[14297] devicestate.c: Notification of state change to be queued on device/channel SIP/421 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421 - state 2 (In use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421-0a0f4860 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421-0a0f4860 [May 29 09:06:43] DEBUG[16641] pbx.c: Launching 'Dial' [May 29 09:06:43] VERBOSE[16641] logger.c: -- Executing [422@user-01:1] Dial("SIP/421-0a0f4860", "SIP/422") in new stack [May 29 09:06:43] DEBUG[16641] chan_sip.c: Asked to create a SIP channel with formats: 0x1000 (g722) [May 29 09:06:43] DEBUG[16641] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 29 09:06:43] DEBUG[16641] chan_sip.c: Setting NAT on RTP to Off [May 29 09:06:43] DEBUG[16641] acl.c: ##### Testing 192.168.161.242 with 192.168.161.0 [May 29 09:06:43] DEBUG[16641] acl.c: ##### Testing 192.168.161.242 with 192.168.200.0 [May 29 09:06:43] DEBUG[16641] acl.c: ##### Testing 192.168.161.242 with 192.168.1.0 [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** Our native formats are 0x8 (alaw) [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** Our capabilities are 0x8 (alaw) [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** Our preferred formats from the incoming channel are 0x1000 (g722) [May 29 09:06:43] DEBUG[16641] chan_sip.c: This channel will not be able to handle video. [May 29 09:06:43] DEBUG[16641] rtp.c: Seeded SDP of 'SIP/422-0a08d310' with that of 'SIP/421-0a0f4860' [May 29 09:06:43] DEBUG[16641] channel.c: Not copying variable SIPCALLID. [May 29 09:06:43] DEBUG[16641] channel.c: Not copying variable SIPUSERAGENT. [May 29 09:06:43] DEBUG[16641] channel.c: Not copying variable SIPDOMAIN. [May 29 09:06:43] DEBUG[16641] channel.c: Not copying variable SIPURI. [May 29 09:06:43] DEBUG[16641] chan_sip.c: Outgoing Call for 422 [May 29 09:06:43] DEBUG[16641] chan_sip.c: Updating call counter for outgoing call [May 29 09:06:43] DEBUG[16641] chan_sip.c: Call to peer '422' is 1 out of 30 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/422 [May 29 09:06:43] WARNING[16641] chan_sip.c: No audio format found to offer. Cancelling call to 422 [May 29 09:06:43] DEBUG[16641] app_dial.c: ast call on peer returned -1 [May 29 09:06:43] VERBOSE[16641] logger.c: -- Couldn't call 422 [May 29 09:06:43] DEBUG[16641] channel.c: Hanging up channel 'SIP/422-0a08d310' [May 29 09:06:43] DEBUG[16641] chan_sip.c: Hangup call SIP/422-0a08d310, SIP callid 022e9c4561ea4f43236157cd13371c10@pbx.example.net) [May 29 09:06:43] DEBUG[16641] chan_sip.c: update_call_counter(422) - decrement call limit counter on hangup [May 29 09:06:43] DEBUG[16641] chan_sip.c: Updating call counter for outgoing call [May 29 09:06:43] DEBUG[16641] chan_sip.c: Call to peer '422' removed from call limit 30 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/422 [May 29 09:06:43] DEBUG[16641] chan_sip.c: Hanging up channel in state Down (not UP) [May 29 09:06:43] VERBOSE[16641] logger.c: Scheduling destruction of SIP dialog '022e9c4561ea4f43236157cd13371c10@pbx.example.net' in 32000 ms (Method: INVITE) [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/422-0a08d310 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/422 [May 29 09:06:43] DEBUG[16641] cdr.c: Dropping CDR ! [May 29 09:06:43] VERBOSE[16641] logger.c: == Everyone is busy/congested at this time (0:0/0/0) [May 29 09:06:43] DEBUG[16641] rtp.c: Channel '' has no RTP, not doing anything [May 29 09:06:43] DEBUG[16641] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [May 29 09:06:43] DEBUG[16641] pbx.c: Launching 'Hangup' [May 29 09:06:43] VERBOSE[16641] logger.c: -- Executing [422@user-01:2] Hangup("SIP/421-0a0f4860", "") in new stack [May 29 09:06:43] DEBUG[16641] pbx.c: Spawn extension (user-01,422,2) exited non-zero on 'SIP/421-0a0f4860' [May 29 09:06:43] VERBOSE[16641] logger.c: == Spawn extension (user-01, 422, 2) exited non-zero on 'SIP/421-0a0f4860' [May 29 09:06:43] DEBUG[16641] channel.c: Soft-Hanging up channel 'SIP/421-0a0f4860' [May 29 09:06:43] DEBUG[16641] pbx.c: Function result is 'Hangup' [May 29 09:06:43] DEBUG[16641] pbx.c: Expression result is '0' [May 29 09:06:43] DEBUG[16641] pbx.c: Launching 'GosubIf' [May 29 09:06:43] VERBOSE[16641] logger.c: -- Executing [h@user-01:1] GosubIf("SIP/421-0a0f4860", "0?macro-endcall|s|VOICEMAIL-CDR") in new stack [May 29 09:06:43] DEBUG[16641] pbx.c: Function result is 'Hangup' [May 29 09:06:43] DEBUG[16641] pbx.c: Expression result is '0' [May 29 09:06:43] DEBUG[16641] pbx.c: Launching 'GosubIf' [May 29 09:06:43] VERBOSE[16641] logger.c: -- Executing [h@user-01:2] GosubIf("SIP/421-0a0f4860", "0?service-04|directoryext|CDR") in new stack [May 29 09:06:43] DEBUG[16641] pbx.c: Launching 'Hangup' [May 29 09:06:43] VERBOSE[16641] logger.c: -- Executing [h@user-01:3] Hangup("SIP/421-0a0f4860", "") in new stack [May 29 09:06:43] DEBUG[16641] pbx.c: Spawn extension (user-01,h,3) exited non-zero on 'SIP/421-0a0f4860' [May 29 09:06:43] VERBOSE[16641] logger.c: == Spawn extension (user-01, h, 3) exited non-zero on 'SIP/421-0a0f4860' [May 29 09:06:43] DEBUG[16641] channel.c: Hanging up channel 'SIP/421-0a0f4860' [May 29 09:06:43] DEBUG[16641] chan_sip.c: Hangup call SIP/421-0a0f4860, SIP callid 3c275dba4a85-2z7732ti3iws) [May 29 09:06:43] DEBUG[16641] chan_sip.c: update_call_counter(421) - decrement call limit counter on hangup [May 29 09:06:43] DEBUG[16641] chan_sip.c: Updating call counter for incoming call [May 29 09:06:43] DEBUG[16641] chan_sip.c: Call from peer '421' removed from call limit 30 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/421 [May 29 09:06:43] DEBUG[16641] chan_sip.c: Hanging up channel in state Ring (not UP) [May 29 09:06:43] VERBOSE[16641] logger.c: Scheduling destruction of SIP dialog '3c275dba4a85-2z7732ti3iws' in 32000 ms (Method: INVITE) [May 29 09:06:43] DEBUG[16641] chan_sip.c: AST hangup cause 16 (no match found in SIP) [May 29 09:06:43] VERBOSE[16641] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.161.233:5060 ---> SIP/2.0 603 Declined Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;received=192.168.161.233;rport=5060 From: "Theo 3" ;tag=iaql6jp6c9 To: ;tag=as5898f559 Call-ID: 3c275dba4a85-2z7732ti3iws CSeq: 2 INVITE User-Agent: atCOM PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 29 09:06:43] DEBUG[16641] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/421-0a0f4860 [May 29 09:06:43] DEBUG[16641] devicestate.c: Notification of state change to be queued on device/channel SIP/421 [May 29 09:06:43] DEBUG[16641] cdr.c: Dropping CDR ! [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421-0a0f4860 - state 4 (Invalid) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/422 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/422 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422-0a08d310 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422-0a08d310 [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421-0a0f4860' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/422' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/422' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/422-0a08d310 - state 4 (Invalid) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/422 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 422 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 422 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421-0a0f4860 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421-0a0f4860 [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/422-0a08d310' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/422' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421-0a0f4860 - state 4 (Invalid) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14278] devicestate.c: Changing state for SIP/421 - state 1 (Not in use) [May 29 09:06:43] DEBUG[14278] devicestate.c: No provider found, checking channel drivers for SIP - 421 [May 29 09:06:43] DEBUG[14278] chan_sip.c: Checking device state for peer 421 [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421-0a0f4860' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 29 09:06:43] DEBUG[14299] app_queue.c: Device 'SIP/421' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 29 09:06:43] VERBOSE[14297] logger.c: <--- SIP read from 192.168.161.233:5060 ---> ACK sip:422@pbx.example.net;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;rport From: "Theo 3" ;tag=iaql6jp6c9 To: ;tag=as5898f559 Call-ID: 3c275dba4a85-2z7732ti3iws CSeq: 2 ACK Max-Forwards: 70 Contact: ;flow-id=1 Content-Length: 0 <-------------> [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 0: ACK sip:422@pbx.example.net;user=phone SIP/2.0 (46) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-qahsd08penfv;rport (71) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 2: From: "Theo 3" ;tag=iaql6jp6c9 (55) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 3: To: ;tag=as5898f559 (55) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 4: Call-ID: 3c275dba4a85-2z7732ti3iws (34) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 5: CSeq: 2 ACK (11) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 7: Contact: ;flow-id=1 (49) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 8: Content-Length: 0 (17) [May 29 09:06:43] DEBUG[14297] chan_sip.c: Header 9: (0) [May 29 09:06:43] VERBOSE[14297] logger.c: --- (9 headers 0 lines) --- [May 29 09:06:43] DEBUG[14297] chan_sip.c: = No match Their Call ID: 022e9c4561ea4f43236157cd13371c10@pbx.example.net Their Tag Our tag: as4dc0a32c [May 29 09:06:43] DEBUG[14297] chan_sip.c: = Found Their Call ID: 3c275dba4a85-2z7732ti3iws Their Tag iaql6jp6c9 Our tag: as5898f559 [May 29 09:06:43] DEBUG[14297] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 29 09:06:43] DEBUG[14297] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1602 [May 29 09:06:43] DEBUG[14297] chan_sip.c: Stopping retransmission on '3c275dba4a85-2z7732ti3iws' of Response 2: Match Found