[Feb 14 09:49:00] DEBUG[1952] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 14 09:49:05] DEBUG[1910] db.c: Unable to find key '(bogus_peer)' in family 'SIP/Registry' [Feb 14 09:49:05] VERBOSE[1891] chan_sip.c: Reloading SIP [Feb 14 09:49:05] DEBUG[1891] config.c: Parsing /etc/asterisk/sip.conf [Feb 14 09:49:05] VERBOSE[1891] config.c: Parsing '/etc/asterisk/sip.conf': Found [Feb 14 09:49:05] DEBUG[1891] config.c: Parsing /etc/asterisk/users.conf [Feb 14 09:49:05] VERBOSE[1891] config.c: Parsing '/etc/asterisk/users.conf': Found [Feb 14 09:49:05] DEBUG[1891] acl.c: Multiple addresses. Using the first only [Feb 14 09:49:05] VERBOSE[1891] netsock2.c: Using SIP CoS mark 4 [Feb 14 09:49:05] DEBUG[1891] tcptls.c: Nothing changed in SIP TCP server [Feb 14 09:49:05] DEBUG[1891] format_cap.c: Packetization for codec: alaw is 40 [Feb 14 09:49:05] DEBUG[1891] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Feb 14 09:49:05] DEBUG[1891] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Feb 14 09:49:05] DEBUG[1891] config.c: Parsing /etc/asterisk/sip_notify.conf [Feb 14 09:49:05] VERBOSE[1891] config.c: Parsing '/etc/asterisk/sip_notify.conf': Found [Feb 14 09:49:05] DEBUG[1891] sched.c: Asterisk Schedule Dump (0 in Q, 67 Total, 6 Cache, 5 high-water) [Feb 14 09:49:05] DEBUG[1891] sched.c: ============================================================= [Feb 14 09:49:05] DEBUG[1891] sched.c: |ID Callback Data Time (sec:ms) | [Feb 14 09:49:05] DEBUG[1891] sched.c: +-----+-----------------+-----------------+-----------------+ [Feb 14 09:49:05] DEBUG[1891] sched.c: ============================================================= [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: Asked to create a SIP channel with formats: (slin) [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: Allocating new SIP dialog for 3ae869544c25c0412c6d21cb57eefa3b@[::1]:5060 - INVITE (No RTP) [Feb 14 09:49:50] DEBUG[1910] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f124c0069b8' [Feb 14 09:49:50] DEBUG[1910] res_rtp_asterisk.c: Allocated port 11932 for RTP instance '0x7f124c0069b8' [Feb 14 09:49:50] DEBUG[1910] rtp_engine.c: RTP instance '0x7f124c0069b8' is setup and ready to go [Feb 14 09:49:50] DEBUG[1910] acl.c: Multiple addresses. Using the first only [Feb 14 09:49:50] DEBUG[1910] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f124c0069b8' [Feb 14 09:49:50] VERBOSE[1910] netsock2.c: Using SIP RTP CoS mark 5 [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: Setting NAT on RTP to Off [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: Setting NAT on RTP to Off [Feb 14 09:49:50] DEBUG[1910] chan_sip.c: SIP call-id changed from '3ae869544c25c0412c6d21cb57eefa3b@[::1]:5060' to '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' [Feb 14 09:49:50] DEBUG[1910] channel.c: Channel 0x7f124c00b588 'SIP/100-00000004' allocated [Feb 14 09:49:50] DEBUG[1955] chan_sip.c: Outgoing Call for 100 [Feb 14 09:49:50] DEBUG[1955] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False [Feb 14 09:49:50] DEBUG[1955] chan_sip.c: ** Our prefcodec: (slin) [Feb 14 09:49:50] VERBOSE[1955] chan_sip.c: Audio is at 11932 [Feb 14 09:49:50] VERBOSE[1955] chan_sip.c: Adding codec alaw to SDP [Feb 14 09:49:50] VERBOSE[1955] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 14 09:49:50] DEBUG[1955] chan_sip.c: Initializing initreq for method INVITE - callid 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 [Feb 14 09:49:50] VERBOSE[1955] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.140:5060: INVITE sip:100@192.168.1.140 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7f62dee6 Max-Forwards: 70 From: "Anonymous" ;tag=as279355b7 To: Contact: Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 15.2.1 Date: Wed, 14 Feb 2018 08:49:50 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 253 v=0 o=root 1055876863 1055876863 IN IP4 192.168.1.172 s=Asterisk PBX 15.2.1 c=IN IP4 192.168.1.172 t=0 0 m=audio 11932 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:40 a=maxptime:150 a=sendrecv --- [Feb 14 09:49:50] VERBOSE[1955] dial.c: Called 100 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: <--- SIP read from UDP:192.168.1.140:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7f62dee6 From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 102 INVITE Contact: Content-Length: 0 <-------------> [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: --- (8 headers 0 lines) --- [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' Request 102: Found [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: <--- SIP read from UDP:192.168.1.140:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7f62dee6 From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 102 INVITE Contact: Content-Length: 0 <-------------> [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: --- (8 headers 0 lines) --- [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' Request 102: Found [Feb 14 09:49:50] VERBOSE[1891] sip/route.c: sip_route_dump: route/path hop: [Feb 14 09:49:50] VERBOSE[1955] dial.c: SIP/100-00000004 is ringing [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: <--- SIP read from UDP:192.168.1.140:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7f62dee6 From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 102 INVITE Contact: Content-Type: application/sdp Content-Length: 138 v=0 o=user1 53655765 2353687637 IN IP4 192.168.1.140 s=- c=IN IP4 192.168.1.140 t=0 0 m=audio 49000 RTP/AVP 8 a=rtpmap:8 PCMA/8000 <-------------> [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: --- (9 headers 7 lines) --- [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: Acked pending invite 102 [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: Stopping retransmission on '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' of Request 102: Match Found [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Found RTP audio format 8 [Feb 14 09:49:50] DEBUG[1891] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f12100b7350 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Found audio description format PCMA for ID 8 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Capabilities: us - (alaw), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [Feb 14 09:49:50] DEBUG[1891] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f124c0069b8' [Feb 14 09:49:50] VERBOSE[1891] res_rtp_asterisk.c: 0x7f124c007910 -- Strict RTP learning after remote address set to: 192.168.1.140:49000 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Peer audio RTP is at port 192.168.1.140:49000 [Feb 14 09:49:50] DEBUG[1891] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f124c0069b8' [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: Setting native formats after processing SDP. peer joint formats (alaw), old nativeformats (alaw) [Feb 14 09:49:50] DEBUG[1891] channel.c: Channel SIP/100-00000004 setting read format path: alaw -> alaw [Feb 14 09:49:50] DEBUG[1891] channel.c: Channel SIP/100-00000004 setting write format path: alaw -> alaw [Feb 14 09:49:50] VERBOSE[1891] sip/route.c: sip_route_dump: route/path hop: [Feb 14 09:49:50] DEBUG[1891] chan_sip.c: Strict routing enforced for session 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: set_destination: Parsing for address/port to send to [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: set_destination: set destination to 192.168.1.140:5060 [Feb 14 09:49:50] VERBOSE[1891] chan_sip.c: Transmitting (no NAT) to 192.168.1.140:5060: ACK sip:192.168.1.140:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7550b038 Max-Forwards: 70 From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Contact: Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 15.2.1 Content-Length: 0 --- [Feb 14 09:49:50] VERBOSE[1955] dial.c: SIP/100-00000004 answered [Feb 14 09:49:50] VERBOSE[1955] pbx.c: Launching MusicOnHold() on SIP/100-00000004 [Feb 14 09:49:50] VERBOSE[1955] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/100-00000004' [Feb 14 09:49:50] DEBUG[1955] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 14 09:49:50] DEBUG[1955] channel.c: Channel SIP/100-00000004 setting write format path: slin -> alaw [Feb 14 09:49:50] DEBUG[1955] res_musiconhold.c: SIP/100-00000004 Opened file 0 '/var/lib/asterisk/moh/macroform-cold_day' [Feb 14 09:49:50] DEBUG[1955] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Feb 14 09:49:50] DEBUG[1955] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f124c0069b8' [Feb 14 09:50:02] DEBUG[1910] channel.c: Soft-Hanging (0x20) up channel 'SIP/100-00000004' [Feb 14 09:50:02] VERBOSE[1955] res_musiconhold.c: Stopped music on hold on SIP/100-00000004 [Feb 14 09:50:02] DEBUG[1955] channel.c: Channel SIP/100-00000004 setting write format path: alaw -> alaw [Feb 14 09:50:02] DEBUG[1955] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 14 09:50:02] DEBUG[1955] channel.c: Channel 0x7f124c00b588 'SIP/100-00000004' hanging up. Refs: 2 [Feb 14 09:50:02] DEBUG[1955] chan_sip.c: Hangup call SIP/100-00000004, SIP callid 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 [Feb 14 09:50:02] VERBOSE[1955] chan_sip.c: Scheduling destruction of SIP dialog '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' in 32000 ms (Method: INVITE) [Feb 14 09:50:02] DEBUG[1955] chan_sip.c: Strict routing enforced for session 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 [Feb 14 09:50:02] VERBOSE[1955] chan_sip.c: set_destination: Parsing for address/port to send to [Feb 14 09:50:02] VERBOSE[1955] chan_sip.c: set_destination: set destination to 192.168.1.140:5060 [Feb 14 09:50:02] VERBOSE[1955] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.140:5060: BYE sip:192.168.1.140:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7889e9df Max-Forwards: 70 From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 103 BYE User-Agent: Asterisk PBX 15.2.1 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Feb 14 09:50:02] DEBUG[1955] channel.c: Channel 0x7f124c00b588 'SIP/100-00000004' destroying [Feb 14 09:50:02] DEBUG[1865] cdr.c: Finalized CDR for SIP/100-00000004 - start 1518598190.398825 answer 1518598190.402599 end 1518598202.758408 dispo ANSWERED [Feb 14 09:50:02] VERBOSE[1891] chan_sip.c: <--- SIP read from UDP:192.168.1.140:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.172:5060;branch=z9hG4bK7889e9df From: "Anonymous" ;tag=as279355b7 To: ;tag=1 Call-ID: 66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060 CSeq: 103 BYE Contact: Content-Length: 0 <-------------> [Feb 14 09:50:02] VERBOSE[1891] chan_sip.c: --- (8 headers 0 lines) --- [Feb 14 09:50:02] DEBUG[1891] chan_sip.c: Stopping retransmission on '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' of Request 103: Match Found [Feb 14 09:50:02] VERBOSE[1891] chan_sip.c: Really destroying SIP dialog '66308f4628f4faae3acd41a61c9787be@192.168.1.172:5060' Method: INVITE [Feb 14 09:50:02] DEBUG[1891] rtp_engine.c: Destroyed RTP instance '0x7f124c0069b8'