[2018-09-05 09:32:31] Asterisk GIT-master-b300c563e8 built by root @ dznet-pbx on a x86_64 running Linux on 2018-09-04 17:11:54 UTC [2018-09-05 09:32:31] DEBUG[20951] config.c: Parsing /etc/asterisk/logger.conf [2018-09-05 09:32:31] ERROR[20951] logger.c: Unable to create queue log: Permission denied [2018-09-05 09:32:31] VERBOSE[20951] logger.c: Asterisk Queue Logger restarted [2018-09-05 09:32:31] VERBOSE[20951] asterisk.c: Remote UNIX connection disconnected [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: inv_session 0x7f94bc457a68 has no ast session [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc42b938 [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:32:32] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:32:35] DEBUG[20869] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:32:35] DEBUG[20862] threadpool.c: Destroying worker thread 9 [2018-09-05 09:32:35] DEBUG[20868] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:32:35] DEBUG[20862] threadpool.c: Destroying worker thread 8 [2018-09-05 09:32:36] DEBUG[20875] res_pjsip_registrar.c: Woke up at 1536157956 Interval: 30 [2018-09-05 09:32:36] DEBUG[20875] res_pjsip_registrar.c: Expiring 0 contacts [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: inv_session 0x7f94c0023dc8 has no ast session [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:32:37] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:32:41] DEBUG[20925] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:32:41] DEBUG[20841] threadpool.c: Destroying worker thread 11 [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP request (3541 bytes) from UDP:192.168.128.12:5060 ---> INVITE sip:@mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.128.12:5060;branch=z9hG4bK3668323708412 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com> Date: Wed, 05 Sep 2018 14:32:47 GMT Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 Supported: 100rel,timer,resource-priority,replaces Min-SE: 1800 User-Agent: Cisco-CP-DX650/10.2.5 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 101 INVITE Expires: 180 Allow-Events: presence Supported: X-cisco-srtp-fallback,X-cisco-original-called Call-Info: ;x-cisco-video-traffic-class=DESKTOP;x-cisco-qos-tcl=true Session-ID: 60a1008300105000a0005017ff96e069;remote=00000000000000000000000000000000 Cisco-Guid: 2377422592-0000065536-0000000428-0209758400 P-Charging-Vector: icid-value="8DB4970000010000000001AB0C80A8C0";icid-generated-at=dznet-ucm;orig-ioi="IMS Inter Operator Identification" Session-Expires: 1800 P-Asserted-Identity: "My Name" @mydomain.com> Remote-Party-ID: "My Name" @mydomain.com>;party=calling;screen=yes;privacy=off Contact: @192.168.128.12:5060>;video;audio;+u.sip!devicename.ccm.cisco.com="SEP5017FF96E069";bfcp Max-Forwards: 69 Content-Type: application/sdp Content-Length: 2098 v=0 o=CiscoSystemsCCM-SIP 434384 1 IN IP4 192.168.128.12 s=SIP Call c=IN IP4 192.168.128.134 b=TIAS:384000 b=AS:384 t=0 0 m=audio 19754 RTP/AVP 108 0 18 101 b=TIAS:64000 a=rtpmap:108 MP4A-LATM/90000 a=fmtp:108 bitrate=64000;profile-level-id=24;object=23 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=trafficclass:conversational.audio.avconf.aq:admitted m=video 19150 RTP/AVP 100 126 97 b=TIAS:384000 a=label:11 a=rtpmap:100 H264/90000 a=fmtp:100 profile-level-id=640016;packetization-mode=1;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=rtpmap:126 H264/90000 a=fmtp:126 profile-level-id=428016;packetization-mode=1;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=rtpmap:97 H264/90000 a=fmtp:97 profile-level-id=428016;packetization-mode=0;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=imageattr:* recv [x=1024,y=600,q=0.60] [x=1280,y=720,q=0.50] a=content:main a=rtcp-fb:* nack pli a=rtcp-fb:* ccm fir a=rtcp-fb:* ccm tmmbr a=trafficclass:conversational.video.avconf.aq:admitted m=video 19476 RTP/AVP 100 126 97 b=TIAS:384000 a=label:12 a=rtpmap:100 H264/90000 a=fmtp:100 profile-level-id=640016;packetization-mode=1;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=rtpmap:126 H264/90000 a=fmtp:126 profile-level-id=428016;packetization-mode=1;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=rtpmap:97 H264/90000 a=fmtp:97 profile-level-id=428016;packetization-mode=0;max-mbps=267300;max-fs=8910;max-rcmd-nalu-size=256000;level-asymmetry-allowed=1;max-fps=6000 a=imageattr:* recv [x=1024,y=600,q=0.60] [x=1280,y=720,q=0.50] a=content:slides a=rtcp-fb:* nack pli a=rtcp-fb:* ccm fir a=rtcp-fb:* ccm tmmbr a=trafficclass:conversational.video.avconf.aq:admitted m=application 19358 UDP/BFCP * a=floorctrl:s-only c-only a=floorid:3 mstrm:12 a=confid:1 a=userid:13 [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=101 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003e to use for Request msg INVITE/cseq=101 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.128.12:5060 matches identify 'cucm' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_endpoint_identifier_ip.c: Identify 'cucm' SIP message matched to endpoint cucm [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003e to use for Request msg INVITE/cseq=101 (rdata0x7f94b00eb548) [2018-09-05 09:32:47] VERBOSE[20865] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'mydomain.com' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (416 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK3668323708412 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com> CSeq: 101 INVITE Server: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is INCOMING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is INCOMING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.134' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.134' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Allocated port 19422 for RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Creating ICE session [::]:19422 (19422) for RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: RTP instance '0x7f94bc4662f8' is setup and ready to go [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f94bc457180) from 0x7f9464ff6470 to 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f94bc00ffd0) from 0x7f9464ff6470 to 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7f94bc445f70) from 0x7f9464ff6470 to 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying rx payload mapping 0 (0x7f94bc457180) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying rx payload mapping 18 (0x7f94bc00ffd0) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying rx payload mapping 101 (0x7f94bc445f70) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 0 (0x7f94bc457180) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 18 (0x7f94bc00ffd0) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 101 (0x7f94bc445f70) from 0x7f9464ff6470 to 0x7f94bc4664d0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Media stream 'audio' handled by audio [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Negotiating incoming SDP media stream 'video' using video SDP handler [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.134' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.134' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Allocated port 19370 for RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Creating ICE session [::]:19370 (19370) for RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: RTP instance '0x7f94bc46bde8' is setup and ready to go [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Crossover copying tx to rx payload mapping 100 (0x7f94bc45efa0) from 0x7f9464ff6470 to 0x7f9464ff6470 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying rx payload mapping 100 (0x7f94bc45efa0) from 0x7f9464ff6470 to 0x7f94bc46bfc0 [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 100 (0x7f94bc45efa0) from 0x7f9464ff6470 to 0x7f94bc46bfc0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Media stream 'video' handled by video [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Declining incoming SDP media stream 'video' at position '2' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Declining incoming SDP media stream '' at position '3' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Method is INVITE [2018-09-05 09:32:47] DEBUG[20865] channel.c: Channel 0x7f94bc46d628 'PJSIP/cucm-00000003' allocated [2018-09-05 09:32:47] DEBUG[20865] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/cucm-00000003 [2018-09-05 09:32:47] DEBUG[20841] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'SIPDOMAIN' is 'mydomain.com' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Expression result is '1' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'GotoIf' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [@home:1] GotoIf("PJSIP/cucm-00000003", "1?numeric") in new stack [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx_builtins.c: Goto (home,,4) [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'EXTEN' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'Gosub' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [@home:4] Gosub("PJSIP/cucm-00000003", "dialprovider,s,1()") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] app_stack.c: Channel PJSIP/cucm-00000003 has no datastore, so we're allocating one. [2018-09-05 09:32:47] DEBUG[20961][C-00000002] app_stack.c: Setting 'ARG1' to '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Function CALLERID(all) result is '"My Name" <>' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'NoOp' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:1] NoOp("PJSIP/cucm-00000003", " printing full callerid -- "My Name" <>") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'SIPDOMAIN' is 'mydomain.com' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'NoOp' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:2] NoOp("PJSIP/cucm-00000003", " printing the sip domain -- mydomain.com") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Function CALLERID(num) result is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'Set' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:3] Set("PJSIP/cucm-00000003", "CALLERID(all)=<>") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'ARG1' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'NoOp' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:4] NoOp("PJSIP/cucm-00000003", " printing the extension -- ") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'ARG1' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Expression result is '0' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'ARG1' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'ARG1' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Function IF(0?:) result is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'Dial' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:5] Dial("PJSIP/cucm-00000003", "PJSIP/@sipbroker-out") in new stack [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Outgoing request not associated with a registration. No mangling necessary. [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c0037d8 'PJSIP/sipbroker-out-00000004' allocated [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f94bc440e68' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Allocated port 19912 for RTP instance '0x7f94bc440e68' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Creating ICE session [::]:19912 (19912) for RTP instance '0x7f94bc440e68' [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] app_dial.c: Called PJSIP/@sipbroker-out [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/sipbroker-out-00000004 setting read format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting write format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting read format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/sipbroker-out-00000004 setting write format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: RTP instance '0x7f94bc440e68' is setup and ready to go [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc440e68' [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f94bc45b7c8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Allocated port 19162 for RTP instance '0x7f94bc45b7c8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Creating ICE session [::]:19162 (19162) for RTP instance '0x7f94bc45b7c8' [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: RTP instance '0x7f94bc45b7c8' is setup and ready to go [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc45b7c8' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Method is INVITE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Outgoing request not associated with a registration. No mangling necessary. [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target 'sipbroker.com' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target 'sipbroker.com' is 'UDP' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Created resolution tracking for target 'sipbroker.com' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Added target 'sipbroker.com' with record type '1', transport 'UDP', and port '5060' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Starting initial resolution using parallel queries for target 'sipbroker.com' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'sipbroker-out(PJSIP/sipbroker-out-00000004)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc461c58) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'sipbroker-out(PJSIP/sipbroker-out-00000004)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc461c58) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Calling [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] All parallel queries completed [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] A record received on target 'sipbroker.com' [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Resolution completed - 1 viable targets [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Address '0' is 204.11.194.25:5060 with transport 'UDP' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc4428f0] Invoking user callback with '1' addresses [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '204.11.194.25' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '204.11.194.25' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Setting external media address to [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (1192 bytes) to UDP:204.11.194.25:5060 ---> INVITE sip:@sipbroker.com:5060 SIP/2.0 Via: SIP/2.0/UDP :5060;rport;branch=z9hG4bKPjedb278b4-7107-4539-b6f3-9dc1b7cd6767 From: ;tag=d976df9a-71a7-4dfb-881b-9576665acb2d To: @sipbroker.com> Contact: :5060> Call-ID: 51aa592f-a3c7-4d47-a6dd-b444603f69a6 CSeq: 5733 INVITE Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Remote-Party-ID: @mydomain.com>;privacy=off;screen=no Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Type: application/sdp Content-Length: 426 v=0 o=- 958539336 958539336 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19912 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 19162 RTP/AVP 99 a=rtpmap:99 H264/90000 a=fmtp:99 max-mbps=267300;max-fs=8910;max-fps=6000;max-rcmd-nalu-size=256000;packetization-mode=1;level-asymmetry-allowed=1 a=sendrecv [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (580 bytes) from UDP:204.11.194.25:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP :5060;rport=1024;branch=z9hG4bKPjedb278b4-7107-4539-b6f3-9dc1b7cd6767 From: ;tag=d976df9a-71a7-4dfb-881b-9576665acb2d To: @sipbroker.com> Call-ID: 51aa592f-a3c7-4d47-a6dd-b444603f69a6 CSeq: 5733 INVITE Server: OpenSer (1.1.0-notls (x86_64/linux)) Content-Length: 0 Warning: 392 204.11.194.25:5060 "Noisy feedback tells: pid=3457 req_src_ip= req_src_port=1024 in_uri=sip:@sipbroker.com:5060 out_uri=sip:@sipbroker.com:5060 via_cnt==1" [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0021e08 for Response msg 100/INVITE/cseq=5733 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/sipbroker-out-00000070 associated with dialog dlg0x7f94c0021e08 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'sipbroker-out(PJSIP/sipbroker-out-00000004)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc461c58) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Response is 100 Trying [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (668 bytes) from UDP:204.11.194.25:5060 ---> SIP/2.0 300 Redirect Via: SIP/2.0/UDP :5060;rport=1024;branch=z9hG4bKPjedb278b4-7107-4539-b6f3-9dc1b7cd6767 From: ;tag=d976df9a-71a7-4dfb-881b-9576665acb2d To: @sipbroker.com>;tag=2b8506bb96abbbb8b95a41b9af69a614.57b3 Call-ID: 51aa592f-a3c7-4d47-a6dd-b444603f69a6 CSeq: 5733 INVITE Contact: sip:@mydomain.com Server: OpenSer (1.1.0-notls (x86_64/linux)) Content-Length: 0 Warning: 392 204.11.194.25:5060 "Noisy feedback tells: pid=3457 req_src_ip= req_src_port=1024 in_uri=sip:@sipbroker.com:5060 out_uri=sip:@mydomain.com via_cnt==1" [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0021e08 for Response msg 300/INVITE/cseq=5733 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/sipbroker-out-00000070 associated with dialog dlg0x7f94c0021e08 [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '204.11.194.25' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '204.11.194.25' and port ''. [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (455 bytes) to UDP:204.11.194.25:5060 ---> ACK sip:@sipbroker.com:5060 SIP/2.0 Via: SIP/2.0/UDP :5060;rport;branch=z9hG4bKPjedb278b4-7107-4539-b6f3-9dc1b7cd6767 From: ;tag=d976df9a-71a7-4dfb-881b-9576665acb2d To: @sipbroker.com>;tag=2b8506bb96abbbb8b95a41b9af69a614.57b3 Call-ID: 51aa592f-a3c7-4d47-a6dd-b444603f69a6 CSeq: 5733 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Response is 300 Redirect [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'sipbroker-out(PJSIP/sipbroker-out-00000004)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc461c58) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is RX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Response is 300 Redirect [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'sipbroker-out(PJSIP/sipbroker-out-00000004)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc461c58) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Completed [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] app_dial.c: Now forwarding PJSIP/cucm-00000003 to 'Local/@unauthenticated' (thanks to PJSIP/sipbroker-out-00000004) [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00bf08 'Local/@unauthenticated-00000001;1' allocated [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00fe88 'Local/@unauthenticated-00000001;2' allocated [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel_internal_api.c: Channel Call ID changing from [C-00000002] to [C-00000002] [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel Local/@unauthenticated-00000001;1 setting read format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting write format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting read format path: ulaw -> ulaw [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel Local/@unauthenticated-00000001;1 setting write format path: ulaw -> ulaw [2018-09-05 09:32:47] NOTICE[20961][C-00000002] app_dial.c: Not accepting call completion offers from call-forward recipient Local/@unauthenticated-00000001;1 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Method is INVITE, Response is 181 Call Is Being Forwarded [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (687 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 181 Call Is Being Forwarded Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK3668323708412 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 CSeq: 101 INVITE Server: Asterisk PBX GIT-master-b300c563e8 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Remote-Party-ID: ;privacy=off;screen=no Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:47] NOTICE[20961][C-00000002] core_local.c: No such extension/context @unauthenticated while calling Local channel [2018-09-05 09:32:47] NOTICE[20961][C-00000002] app_dial.c: Forwarding failed to dial 'Local/@unauthenticated' [2018-09-05 09:32:47] DEBUG[20860] cdr.c: Finalized CDR for PJSIP/cucm-00000003 - start 1536157967.209262 answer 0.000000 end 1536157967.379347 dispo FAILED [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c0037d8 'PJSIP/sipbroker-out-00000004' hanging up. Refs: 2 [2018-09-05 09:32:47] DEBUG[20961][C-00000002] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Destroying SIP session with endpoint sipbroker-out [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Destroyed RTP instance '0x7f94bc440e68' [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Destroyed RTP instance '0x7f94bc45b7c8' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c0037d8 'PJSIP/sipbroker-out-00000004' destroying [2018-09-05 09:32:47] DEBUG[20860] cdr.c: Finalized CDR for PJSIP/sipbroker-out-00000004 - start 1536157967.209999 answer 0.000000 end 1536157967.379461 dispo FAILED [2018-09-05 09:32:47] DEBUG[20860] cdr.c: CDR for PJSIP/sipbroker-out-00000004 is dialed and has no Party B; discarding [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - sipbroker-out [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: Changing state for PJSIP/sipbroker-out - state 1 (Not in use) [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00bf08 'Local/@unauthenticated-00000001;1' hanging up. Refs: 2 [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00fe88 'Local/@unauthenticated-00000001;2' hanging up. Refs: 3 [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00fe88 'Local/@unauthenticated-00000001;2' destroying [2018-09-05 09:32:47] DEBUG[20860] cdr.c: Finalized CDR for Local/@unauthenticated-00000001;2 - start 1536157967.379072 answer 0.000000 end 1536157967.379649 dispo FAILED [2018-09-05 09:32:47] DEBUG[20860] cdr.c: Skipping CDR for Local/@unauthenticated-00000001;2 since we weren't answered [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for Local - @unauthenticated [2018-09-05 09:32:47] DEBUG[20852] core_local.c: Checking if extension @unauthenticated exists (devicestate) [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: Changing state for Local/@unauthenticated - state 4 (Invalid) [2018-09-05 09:32:47] DEBUG[20894] app_queue.c: Device 'Local/@unauthenticated' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00bf08 'Local/@unauthenticated-00000001;1' destroying [2018-09-05 09:32:47] DEBUG[20860] cdr.c: Finalized CDR for Local/@unauthenticated-00000001;1 - start 1536157967.379021 answer 0.000000 end 1536157967.379763 dispo FAILED [2018-09-05 09:32:47] DEBUG[20860] cdr.c: CDR for Local/@unauthenticated-00000001;1 is dialed and has no Party B; discarding [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for Local - @unauthenticated [2018-09-05 09:32:47] DEBUG[20852] core_local.c: Checking if extension @unauthenticated exists (devicestate) [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: Changing state for Local/@unauthenticated - state 4 (Invalid) [2018-09-05 09:32:47] DEBUG[20894] app_queue.c: Device 'Local/@unauthenticated' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] app_dial.c: Everyone is busy/congested at this time (1:0/0/1) [2018-09-05 09:32:47] DEBUG[20961][C-00000002] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'NoOp' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:6] NoOp("PJSIP/cucm-00000003", " Dial Status: CHANUNAVAIL") in new stack [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'Goto' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s@dialprovider:7] Goto("PJSIP/cucm-00000003", "s-CHANUNAVAIL,1") in new stack [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx_builtins.c: Goto (dialprovider,s-CHANUNAVAIL,1) [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Result of 'ARG1' is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx_variables.c: Function CALLERID(num) result is '' [2018-09-05 09:32:47] DEBUG[20961][C-00000002] pbx.c: Launching 'Dial' [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] pbx.c: Executing [s-CHANUNAVAIL@dialprovider:1] Dial("PJSIP/cucm-00000003", "PJSIP/@,,r") in new stack [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Setting transport to 0x7f94bc41faa8 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip.c: Overriding endpoint transport to use 0x7f94bc41faa8 [2018-09-05 09:32:47] DEBUG[20961][C-00000002] channel.c: Channel 0x7f948c00ddd8 'PJSIP/-00000005' allocated [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Allocated port 19102 for RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Creating ICE session [::]:19102 (19102) for RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] VERBOSE[20961][C-00000002] app_dial.c: Called PJSIP/@ [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - cucm [2018-09-05 09:32:47] DEBUG[20852] devicestate.c: Changing state for PJSIP/cucm - state 2 (In use) [2018-09-05 09:32:47] DEBUG[20894] app_queue.c: Device 'PJSIP/cucm' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [2018-09-05 09:32:47] DEBUG[20866] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:47] DEBUG[20866] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:47] DEBUG[20866] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:32:47] VERBOSE[20866] res_pjsip_logger.c: <--- Transmitting SIP response (671 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK3668323708412 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 CSeq: 101 INVITE Server: Asterisk PBX GIT-master-b300c563e8 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Contact: Remote-Party-ID: ;privacy=off;screen=no Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:47] DEBUG[20866] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] rtp_engine.c: RTP instance '0x7f94bc4645a8' is setup and ready to go [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting 'fe80::20c:29ff:fe43:c08d' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host 'fe80::20c:29ff:fe43:c08d' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '192.168.128.7' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '192.168.128.7' and port ''. [2018-09-05 09:32:47] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Method is INVITE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Found matching outbound registration state [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Found service-route. Adding route header for [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_outbound_registration.c: Found service-route. Adding route header for [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target 'obihai.telephony.goog' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target 'obihai.telephony.goog' is 'TLS' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Created resolution tracking for target 'obihai.telephony.goog' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Added target 'obihai.telephony.goog' with record type '1', transport 'TLS', and port '5061' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Starting initial resolution using parallel queries for target 'obihai.telephony.goog' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Calling [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] All parallel queries completed [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] A record received on target 'obihai.telephony.goog' [2018-09-05 09:32:47] DEBUG[20874] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Resolution completed - 1 viable targets [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Address '0' is 64.9.242.108:5061 with transport 'TLS' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: [0x7f94bc493c50] Invoking user callback with '1' addresses [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5061 (this may be re-written again later) [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (2037 bytes) to TLS:64.9.242.108:5061 ---> INVITE sip:@obihai.sip.google.com SIP/2.0 Via: SIP/2.0/TLS 192.168.128.7:5061;rport;branch=z9hG4bKPjf05171e4-eca8-4383-8606-ee1567217542;alias From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 To: @obihai.sip.google.com> Contact: Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 INVITE Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub, path, outbound Session-Expires: 1800 Min-SE: 90 Route: Route: P-Preferred-Identity: Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Type: application/sdp Content-Length: 843 v=0 o=- 366538979 366538979 IN IP4 192.168.128.7 s=Asterisk c=IN IP4 192.168.128.7 t=0 0 m=audio 19102 RTP/AVP 0 101 a=ice-ufrag:515d4e6042d5611c34a8d9121196348c a=ice-pwd:09536e26106301c20420f840206dc794 a=candidate:Ha6e76162 1 UDP 2130706431 fe80::20c:29ff:fe43:c08d 19102 typ host a=candidate:Hc0a88007 1 UDP 2130706431 192.168.128.7 19102 typ host a=candidate:S45829cd3 1 UDP 1694498815 19102 typ srflx raddr 192.168.128.7 rport 19102 a=candidate:Ha6e76162 2 UDP 2130706430 fe80::20c:29ff:fe43:c08d 19103 typ host a=candidate:Hc0a88007 2 UDP 2130706430 192.168.128.7 19103 typ host a=candidate:S45829cd3 2 UDP 1694498814 19103 typ srflx raddr 192.168.128.7 rport 19103 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv a=rtcp-mux [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (547 bytes) from TLS:64.9.242.108:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/TLS 192.168.128.7:5061;rport=45477;branch=z9hG4bKPjf05171e4-eca8-4383-8606-ee1567217542;received=;alias Record-Route: Record-Route: To: @obihai.sip.google.com> From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 INVITE Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94bc42b938 for Response msg 100/INVITE/cseq=8011 (rdata0x7f94bc41fdc0) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/-00000071 associated with dialog dlg0x7f94bc42b938 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: The current inv state is CALLING [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_session.c: Response is 100 Trying [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP request (669 bytes) from UDP::44507 ---> SUBSCRIBE sip::5060 SIP/2.0 Via: SIP/2.0/UDP :44507;branch=z9hG4bK1211582538;rport From: @dznet-pbx.mydomain.com>;tag=107759677 To: @dznet-pbx.mydomain.com>;tag=accdac79-58ef-48d6-8288-d90fdc218f9d Call-ID: 848737224-44507-7@BA.A.A.CG CSeq: 20067 SUBSCRIBE Contact: @:44507> Max-Forwards: 70 Supported: replaces, path, timer, eventlist User-Agent: Grandstream GXV3140 1.0.7.80 Expires: 900 Event: message-summary Accept: application/simple-message-summary Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0006598 for Request msg SUBSCRIBE/cseq=20067 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000032 associated with dialog dlg0x7f94c0006598 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: evsub 0x7f94c0008dc8 sub_tree 0x7f94c0006098 sub_tree state Normal [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: Cancelling timer: ->/message-summary 848737224-44507-7@BA.A.A.CG [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: Updating persistence for '->' prune on boot: no [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (603 bytes) to UDP::44507 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :44507;rport=44507;received=;branch=z9hG4bK1211582538 Call-ID: 848737224-44507-7@BA.A.A.CG From: @dznet-pbx.mydomain.com>;tag=107759677 To: @dznet-pbx.mydomain.com>;tag=accdac79-58ef-48d6-8288-d90fdc218f9d CSeq: 20067 SUBSCRIBE Expires: 900 Contact: :5060> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: sub_tree 0x7f94c0006098 sub_tree state Normal [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: sub_tree 0x7f94c0006098 sub_tree state Normal [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target '' is 'UDP' [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_resolver.c: Target '' is an IP address, skipping resolution [2018-09-05 09:32:47] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: Splitting '' into... [2018-09-05 09:32:47] DEBUG[20865] netsock2.c: ...host '' and port ''. [2018-09-05 09:32:47] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (702 bytes) to UDP::44507 ---> NOTIFY sip:@:44507 SIP/2.0 Via: SIP/2.0/UDP :5060;rport;branch=z9hG4bKPj6c6f8f7f-58b0-435e-9179-2e96317cff1e From: @dznet-pbx.mydomain.com>;tag=accdac79-58ef-48d6-8288-d90fdc218f9d To: @dznet-pbx.mydomain.com>;tag=107759677 Contact: :5060> Call-ID: 848737224-44507-7@BA.A.A.CG CSeq: 20042 NOTIFY Event: message-summary Subscription-State: active;expires=900 Allow-Events: message-summary, presence, dialog, refer Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 1/0 (0/0) [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: evsub 0x7f94c0008dc8 state ACTIVE event USER sub_tree 0x7f94c0006098 sub_tree state Normal [2018-09-05 09:32:47] DEBUG[20865] res_pjsip_pubsub.c: Updating persistence for '->' prune on boot: no [2018-09-05 09:32:47] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (631 bytes) from UDP::44507 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :5060;rport=5060;branch=z9hG4bKPj6c6f8f7f-58b0-435e-9179-2e96317cff1e From: @dznet-pbx.mydomain.com>;tag=accdac79-58ef-48d6-8288-d90fdc218f9d To: @dznet-pbx.mydomain.com>;tag=107759677 Call-ID: 848737224-44507-7@BA.A.A.CG CSeq: 20042 NOTIFY Contact: @:44507> Supported: replaces, path, timer, eventlist User-Agent: Grandstream GXV3140 1.0.7.80 Warning: 399 10.0.0.26 "Detected NAT type is UDP Blocked" Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0006598 for Response msg 200/NOTIFY/cseq=20042 (rdata0x7f94b000b278) [2018-09-05 09:32:47] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000032 associated with dialog dlg0x7f94c0006598 [2018-09-05 09:32:48] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (1363 bytes) from TLS:64.9.242.108:5061 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/TLS 192.168.128.7:5061;rport=45477;branch=z9hG4bKPjf05171e4-eca8-4383-8606-ee1567217542;received=;alias Record-Route: Record-Route: Contact: @AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ> To: @obihai.sip.google.com>;tag=1761696072 From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 INVITE Allow: ACK, BYE, CANCEL, INVITE, UPDATE Content-Type: application/sdp Content-Length: 565 v=0 o=- 687789862 1536157968082 IN IP4 74.125.39.26 s=SIP Call c=IN IP4 74.125.39.26 t=0 0 a=ice-lite a=ice-pwd:rgQFkE/OL3SGwOqPqpU2UM75 a=ice-ufrag:VFKUP7kYeuh9MVY6 a=group:BUNDLE audio a=fingerprint:sha-256 43:EE:1C:08:FA:CD:F9:8C:BB:29:99:AE:9E:A1:63:FC:4C:8D:89:2B:87:9E:9F:A5:52:9A:60:49:A2:BF:BD:90 a=setup:passive m=audio 19305 RTP/AVP 0 101 a=mid:audio a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=rtcp-mux a=candidate:1 1 UDP 1 74.125.39.26 19305 typ host a=candidate:2 1 UDP 2 2001:4860:4864:2::26 19305 typ host a=sendrecv [2018-09-05 09:32:48] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94bc42b938 for Response msg 183/INVITE/cseq=8011 (rdata0x7f94bc41fdc0) [2018-09-05 09:32:48] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/-00000071 associated with dialog dlg0x7f94bc42b938 [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is RX_MSG [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Response is 183 Session Progress [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: Splitting 'dznet-pbx' into... [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: ...host 'dznet-pbx' and port ''. [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: Splitting '74.125.39.26' into... [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: ...host '74.125.39.26' and port ''. [2018-09-05 09:32:48] DEBUG[20865] acl.c: For destination '74.125.39.26', our source address is '192.168.128.7'. [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:48] VERBOSE[20865] res_rtp_asterisk.c: 0x7f94bc44d8a0 -- Strict RTP learning after remote address set to: 74.125.39.26:19305 [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: Splitting '74.125.39.26' into... [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: ...host '74.125.39.26' and port ''. [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: Splitting '2001:4860:4864:2::26' into... [2018-09-05 09:32:48] DEBUG[20865] netsock2.c: ...host '2001:4860:4864:2::26' and port ''. [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Set role to CONTROLLING (0x7f94bc4645a8) [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [2018-09-05 09:32:48] DEBUG[20865] res_rtp_asterisk.c: Successfully created ICE checklist (0x7f94bc4645a8) [2018-09-05 09:32:48] ERROR[20865] pjproject: icess0x7f94bc4726f8 ......Error sending STUN request: Network is unreachable [2018-09-05 09:32:48] DEBUG[20865] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f9464ff5ec0 [2018-09-05 09:32:48] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 0 (0x7f94bc442170) from 0x7f9464ff5ec0 to 0x7f94bc464780 [2018-09-05 09:32:48] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 101 (0x7f94bc440930) from 0x7f9464ff5ec0 to 0x7f94bc464780 [2018-09-05 09:32:48] DEBUG[20865] channel.c: Channel PJSIP/-00000005 setting read format path: ulaw -> ulaw [2018-09-05 09:32:48] DEBUG[20865] channel.c: Channel PJSIP/-00000005 setting write format path: ulaw -> ulaw [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:48] DEBUG[20865] res_pjsip_session.c: Response is 183 Session Progress [2018-09-05 09:32:48] VERBOSE[20961][C-00000002] app_dial.c: PJSIP/-00000005 is making progress passing it to PJSIP/cucm-00000003 [2018-09-05 09:32:48] VERBOSE[20961][C-00000002] app_dial.c: PJSIP/-00000005 is making progress passing it to PJSIP/cucm-00000003 [2018-09-05 09:32:48] DEBUG[20876] netsock2.c: Splitting '74.125.39.26' into... [2018-09-05 09:32:48] DEBUG[20876] netsock2.c: ...host '74.125.39.26' and port ''. [2018-09-05 09:32:48] DEBUG[20876] acl.c: For destination '74.125.39.26', our source address is '192.168.128.7'. [2018-09-05 09:32:48] DEBUG[20876] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:48] VERBOSE[20876] res_rtp_asterisk.c: 0x7f94bc44d8a0 -- Strict RTP learning after ICE completion [2018-09-05 09:32:49] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (756 bytes) from TLS:64.9.242.108:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/TLS 192.168.128.7:5061;rport=45477;branch=z9hG4bKPjf05171e4-eca8-4383-8606-ee1567217542;received=;alias Record-Route: Record-Route: Contact: @AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ> To: @obihai.sip.google.com>;tag=1761696072 From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 INVITE Allow: ACK, BYE, CANCEL, INVITE, UPDATE Content-Length: 0 [2018-09-05 09:32:49] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94bc42b938 for Response msg 180/INVITE/cseq=8011 (rdata0x7f94bc41fdc0) [2018-09-05 09:32:49] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/-00000071 associated with dialog dlg0x7f94bc42b938 [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is RX_MSG [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Response is 180 Ringing [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Response is 180 Ringing [2018-09-05 09:32:49] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - [2018-09-05 09:32:49] DEBUG[20852] devicestate.c: Changing state for PJSIP/ - state 6 (Ringing) [2018-09-05 09:32:49] DEBUG[20894] app_queue.c: Device 'PJSIP/' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2018-09-05 09:32:49] VERBOSE[20961][C-00000002] app_dial.c: PJSIP/-00000005 is ringing [2018-09-05 09:32:49] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - cucm [2018-09-05 09:32:49] DEBUG[20852] devicestate.c: Changing state for PJSIP/cucm - state 2 (In use) [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [2018-09-05 09:32:49] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:49] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:49] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:32:49] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (683 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK3668323708412 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 CSeq: 101 INVITE Server: Asterisk PBX GIT-master-b300c563e8 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Contact: Remote-Party-ID: ;privacy=off;screen=no Content-Length: 0 [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current transaction state is Proceeding [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:49] DEBUG[20865] res_pjsip_session.c: The current inv state is EARLY [2018-09-05 09:32:49] VERBOSE[20961][C-00000002] app_dial.c: PJSIP/-00000005 is ringing [2018-09-05 09:32:52] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (1349 bytes) from TLS:64.9.242.108:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.128.7:5061;rport=45477;branch=z9hG4bKPjf05171e4-eca8-4383-8606-ee1567217542;received=;alias Record-Route: Record-Route: Contact: @AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ> To: @obihai.sip.google.com>;tag=1761696072 From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 INVITE Allow: ACK, BYE, CANCEL, INVITE, UPDATE Content-Type: application/sdp Content-Length: 565 v=0 o=- 687789862 1536157968082 IN IP4 74.125.39.26 s=SIP Call c=IN IP4 74.125.39.26 t=0 0 a=ice-lite a=ice-pwd:rgQFkE/OL3SGwOqPqpU2UM75 a=ice-ufrag:VFKUP7kYeuh9MVY6 a=group:BUNDLE audio a=fingerprint:sha-256 43:EE:1C:08:FA:CD:F9:8C:BB:29:99:AE:9E:A1:63:FC:4C:8D:89:2B:87:9E:9F:A5:52:9A:60:49:A2:BF:BD:90 a=setup:passive m=audio 19305 RTP/AVP 0 101 a=mid:audio a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=rtcp-mux a=candidate:1 1 UDP 1 74.125.39.26 19305 typ host a=candidate:2 1 UDP 2 2001:4860:4864:2::26 19305 typ host a=sendrecv [2018-09-05 09:32:52] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94bc42b938 for Response msg 200/INVITE/cseq=8011 (rdata0x7f94bc41fdc0) [2018-09-05 09:32:52] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/-00000071 associated with dialog dlg0x7f94bc42b938 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONNECTING [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is RX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Response is 200 OK [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '64.9.242.108' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target '64.9.242.108' is 'TLS' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Target '64.9.242.108' is an IP address, skipping resolution [2018-09-05 09:32:52] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (715 bytes) to TLS:64.9.242.108:5061 ---> ACK sip:@AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ SIP/2.0 Via: SIP/2.0/TLS 192.168.128.7:5061;rport;branch=z9hG4bKPjf5669305-1b8b-4156-af35-1e3420321e3e;alias From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 To: @obihai.sip.google.com>;tag=1761696072 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8011 ACK Route: Route: Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONFIRMED [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONFIRMED [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Response is 200 OK [2018-09-05 09:32:52] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - [2018-09-05 09:32:52] DEBUG[20852] devicestate.c: Changing state for PJSIP/ - state 2 (In use) [2018-09-05 09:32:52] DEBUG[20894] app_queue.c: Device 'PJSIP/' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2018-09-05 09:32:52] VERBOSE[20961][C-00000002] app_dial.c: PJSIP/-00000005 answered PJSIP/cucm-00000003 [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/-00000005 setting read format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting write format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting read format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/-00000005 setting write format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - cucm [2018-09-05 09:32:52] DEBUG[20852] devicestate.c: Changing state for PJSIP/cucm - state 2 (In use) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [2018-09-05 09:32:52] DEBUG[20865] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: Splitting '192.168.128.134' into... [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: ...host '192.168.128.134' and port ''. [2018-09-05 09:32:52] DEBUG[20865] acl.c: For destination '192.168.128.134', our source address is '192.168.128.7'. [2018-09-05 09:32:52] DEBUG[20865] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f94bc4662f8' [2018-09-05 09:32:52] VERBOSE[20865] res_rtp_asterisk.c: 0x7f94bc446a70 -- Strict RTP learning after remote address set to: 192.168.128.134:19754 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f9464ff6070 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f9464ff6070 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 0 (0x7f94bc46c920) from 0x7f9464ff6070 to 0x7f94bc4664d0 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 18 (0x7f94bc43cda0) from 0x7f9464ff6070 to 0x7f94bc4664d0 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 101 (0x7f94bc491070) from 0x7f9464ff6070 to 0x7f94bc4664d0 [2018-09-05 09:32:52] DEBUG[20865] channel.c: Channel PJSIP/cucm-00000003 setting read format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20865] channel.c: Channel PJSIP/cucm-00000003 setting write format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Applying negotiated SDP media stream 'video' using video SDP handler [2018-09-05 09:32:52] DEBUG[20865] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: Splitting '192.168.128.134' into... [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: ...host '192.168.128.134' and port ''. [2018-09-05 09:32:52] DEBUG[20865] acl.c: For destination '192.168.128.134', our source address is '192.168.128.7'. [2018-09-05 09:32:52] DEBUG[20865] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f94bc46bde8' [2018-09-05 09:32:52] VERBOSE[20865] res_rtp_asterisk.c: 0x7f94bc44acf0 -- Strict RTP learning after remote address set to: 192.168.128.134:19150 [2018-09-05 09:32:52] DEBUG[20865] rtp_engine.c: Copying tx payload mapping 100 (0x7f94bc4d58c0) from 0x7f9464ff6070 to 0x7f94bc46bfc0 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Applied negotiated SDP media stream 'video' using video SDP handler [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Method is INVITE, Response is 200 OK [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5060 (this may be re-written again later) [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:32:52] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:32:52] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (1287 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK3668323708412 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 CSeq: 101 INVITE Server: Asterisk PBX GIT-master-b300c563e8 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Contact: Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Remote-Party-ID: ;privacy=off;screen=no Content-Type: application/sdp Content-Length: 474 v=0 o=- 434384 3 IN IP4 192.168.128.7 s=Asterisk c=IN IP4 192.168.128.7 t=0 0 m=audio 19422 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv m=video 19370 RTP/AVP 100 a=rtpmap:100 H264/90000 a=fmtp:100 max-mbps=267300;max-fs=8910;max-fps=6000;max-rcmd-nalu-size=256000;packetization-mode=1;level-asymmetry-allowed=1 a=sendrecv m=video 0 RTP/AVP 100 126 97 m=application 0 UDP/BFCP * [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONNECTING [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is TX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94c001c628) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current transaction state is Completed [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONNECTING [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge_native_rtp.c: Bridge '771dc477-b011-416b-af1a-7e8fb22be7de' can not use native RTP bridge as two channels are required [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Chose bridge technology simple_bridge [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: calling simple_bridge technology constructor [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: calling simple_bridge technology start [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c013798(PJSIP/-00000005) is joining [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: pushing 0x7f948c013798(PJSIP/-00000005) [2018-09-05 09:32:52] VERBOSE[20969][C-00000002] bridge_channel.c: Channel PJSIP/-00000005 joined 'simple_bridge' basic-bridge <771dc477-b011-416b-af1a-7e8fb22be7de> [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge_native_rtp.c: Bridge '771dc477-b011-416b-af1a-7e8fb22be7de' can not use native RTP bridge as two channels are required [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Chose bridge technology simple_bridge [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de is already using the new technology. [2018-09-05 09:32:52] DEBUG[20969][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c013798(PJSIP/-00000005) is joining simple_bridge technology [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c011798(PJSIP/cucm-00000003) is joining [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: pushing 0x7f948c011798(PJSIP/cucm-00000003) [2018-09-05 09:32:52] VERBOSE[20961][C-00000002] bridge_channel.c: Channel PJSIP/cucm-00000003 joined 'simple_bridge' basic-bridge <771dc477-b011-416b-af1a-7e8fb22be7de> [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge_native_rtp.c: Bridge '771dc477-b011-416b-af1a-7e8fb22be7de'. Checking compatability for channels 'PJSIP/-00000005' and 'PJSIP/cucm-00000003' [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge_native_rtp.c: Bridge '771dc477-b011-416b-af1a-7e8fb22be7de' can not use native RTP bridge as it was forbidden while getting details [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Chose bridge technology simple_bridge [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de is already using the new technology. [2018-09-05 09:32:52] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c011798(PJSIP/cucm-00000003) is joining simple_bridge technology [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting read format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/-00000005 setting write format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/-00000005 setting read format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20961][C-00000002] channel.c: Channel PJSIP/cucm-00000003 setting write format path: ulaw -> ulaw [2018-09-05 09:32:52] DEBUG[20841] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-09-05 09:32:52] DEBUG[20865] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Method is INVITE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_outbound_registration.c: Found matching outbound registration state [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_outbound_registration.c: Found service-route. Adding route header for [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_outbound_registration.c: Found service-route. Adding route header for [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '64.9.242.108' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target '64.9.242.108' is 'TLS' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_resolver.c: Target '64.9.242.108' is an IP address, skipping resolution [2018-09-05 09:32:52] DEBUG[20865] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.128.7:5061 (this may be re-written again later) [2018-09-05 09:32:52] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (2346 bytes) to TLS:64.9.242.108:5061 ---> INVITE sip:@AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ SIP/2.0 Via: SIP/2.0/TLS 192.168.128.7:5061;rport;branch=z9hG4bKPjb53d687f-7db8-4ccb-88fa-b00847e773dc;alias From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 To: @obihai.sip.google.com>;tag=1761696072 Contact: Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8012 INVITE Route: Route: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub, path, outbound Session-Expires: 1800 Min-SE: 90 Route: Route: P-Preferred-Identity: Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Type: application/sdp Content-Length: 865 v=0 o=- 366538979 366538980 IN IP4 192.168.128.7 s=Asterisk c=IN IP4 192.168.128.7 t=0 0 m=audio 19102 RTP/AVP 0 101 a=ice-ufrag:515d4e6042d5611c34a8d9121196348c a=ice-pwd:09536e26106301c20420f840206dc794 a=candidate:Ha6e76162 1 UDP 2130706431 fe80::20c:29ff:fe43:c08d 19102 typ host a=candidate:Hc0a88007 1 UDP 2130706431 192.168.128.7 19102 typ host a=candidate:S45829cd3 1 UDP 1694498815 19102 typ srflx raddr 192.168.128.7 rport 19102 a=candidate:Ha6e76162 2 UDP 2130706430 fe80::20c:29ff:fe43:c08d 19103 typ host a=candidate:Hc0a88007 2 UDP 2130706430 192.168.128.7 19103 typ host a=candidate:S45829cd3 2 UDP 1694498814 19103 typ srflx raddr 192.168.128.7 rport 19103 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv a=rtcp-mux m=video 0 RTP/AVP 32 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current transaction state is Calling [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONFIRMED [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Delay sending reinvite to because of outstanding transaction... [2018-09-05 09:32:52] DEBUG[20860] cdr.c: Finalized CDR for PJSIP/-00000005 - start 1536157967.380454 answer 1536157972.970069 end 1536157972.971376 dispo ANSWERED [2018-09-05 09:32:52] DEBUG[20969][C-00000002] channel.c: Dropping duplicate answer! [2018-09-05 09:32:52] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP request (504 bytes) from UDP:192.168.128.12:5060 ---> ACK sip:192.168.128.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.128.12:5060;branch=z9hG4bK366852e75c014 From: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 To: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 Date: Wed, 05 Sep 2018 14:32:47 GMT Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 User-Agent: Cisco-CP-DX650/10.2.5 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: presence Content-Length: 0 [2018-09-05 09:32:52] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0019278 for Request msg ACK/cseq=101 (rdata0x7f94b000b278) [2018-09-05 09:32:52] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003e associated with dialog dlg0x7f94c0019278 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f94c001c628 [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The transaction state change event is USER [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONNECTING [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: The current inv state is CONFIRMED [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Received request [2018-09-05 09:32:52] DEBUG[20865] res_pjsip_session.c: Method is ACK [2018-09-05 09:32:53] VERBOSE[20961][C-00000002] res_rtp_asterisk.c: 0x7f94bc446a70 -- Strict RTP switching to RTP target address 192.168.128.134:19754 as source [2018-09-05 09:32:53] DEBUG[20969][C-00000002] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2018-09-05 09:32:53] DEBUG[20969][C-00000002] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f94bc4645a8' [2018-09-05 09:32:53] VERBOSE[20969][C-00000002] res_rtp_asterisk.c: 0x7f94bc44d8a0 -- Strict RTP switching to RTP target address 74.125.39.26:19305 as source [2018-09-05 09:32:53] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2018-09-05 09:32:53] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 40 bytes from 192.168.128.134:19151 [2018-09-05 09:32:53] VERBOSE[20969][C-00000002] res_rtp_asterisk.c: 0x7f94bc44d8a0 -- Strict RTP learning complete - Locking on source address 74.125.39.26:19305 [2018-09-05 09:32:53] VERBOSE[20961][C-00000002] res_rtp_asterisk.c: 0x7f94bc44acf0 -- Strict RTP switching to RTP target address 192.168.128.134:19150 as source [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f94bc45f3d8 [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:32:53] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:32:53] DEBUG[20865] res_pjsip_session.c: Destroying SIP session with endpoint cucm [2018-09-05 09:32:57] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 192.168.128.134:19755 [2018-09-05 09:32:57] VERBOSE[20961][C-00000002] res_rtp_asterisk.c: 0x7f94bc446a70 -- Strict RTP learning complete - Locking on source address 192.168.128.134:19754 [2018-09-05 09:32:58] VERBOSE[20961][C-00000002] res_rtp_asterisk.c: 0x7f94bc44acf0 -- Strict RTP learning complete - Locking on source address 192.168.128.134:19150 [2018-09-05 09:32:59] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19151 [2018-09-05 09:33:02] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19755 [2018-09-05 09:33:02] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP request (398 bytes) from UDP:192.168.128.12:5060 ---> OPTIONS sip:mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.128.12:5060;branch=z9hG4bK36686340ccd40 From: ;tag=146399377 To: Date: Wed, 05 Sep 2018 14:33:02 GMT Call-ID: 96a56880-b8f1e91e-35f78-c80a8c0@192.168.128.12 User-Agent: Cisco-CUCM11.5 CSeq: 101 OPTIONS Contact: Max-Forwards: 0 Content-Length: 0 [2018-09-05 09:33:02] DEBUG[20864] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=101 (rdata0x7f94b000b278) [2018-09-05 09:33:02] DEBUG[20864] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000035 to use for Request msg OPTIONS/cseq=101 (rdata0x7f94b000b278) [2018-09-05 09:33:02] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:33:02] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:33:02] DEBUG[20865] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.128.12:5060 matches identify 'cucm' [2018-09-05 09:33:02] DEBUG[20865] res_pjsip_endpoint_identifier_ip.c: Identify 'cucm' SIP message matched to endpoint cucm [2018-09-05 09:33:02] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:33:02] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:33:02] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:33:02] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:192.168.128.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.128.12:5060;rport=5060;received=192.168.128.12;branch=z9hG4bK36686340ccd40 Call-ID: 96a56880-b8f1e91e-35f78-c80a8c0@192.168.128.12 From: ;tag=146399377 To: ;tag=z9hG4bK36686340ccd40 CSeq: 101 OPTIONS Accept: application/pidf+xml, application/simple-message-summary, application/dialog-info+xml, application/xpidf+xml, application/cpim-pidf+xml, application/simple-message-summary, application/pidf+xml, application/dialog-info+xml, application/sdp, message/sipfrag;version=2.0 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Accept-Encoding: text/plain Accept-Language: en Server: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:33:04] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 192.168.128.134:19151 [2018-09-05 09:33:06] DEBUG[20875] res_pjsip_registrar.c: Woke up at 1536157986 Interval: 30 [2018-09-05 09:33:06] DEBUG[20875] res_pjsip_registrar.c: Expiring 0 contacts [2018-09-05 09:33:07] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19755 [2018-09-05 09:33:09] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 192.168.128.134:19151 [2018-09-05 09:33:12] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19755 [2018-09-05 09:33:12] DEBUG[20962] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:12] DEBUG[20841] threadpool.c: Destroying worker thread 14 [2018-09-05 09:33:12] DEBUG[20970] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:12] DEBUG[20841] threadpool.c: Destroying worker thread 15 [2018-09-05 09:33:13] DEBUG[20870] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:13] DEBUG[20840] threadpool.c: Destroying worker thread 10 [2018-09-05 09:33:13] DEBUG[20867] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:13] DEBUG[20862] threadpool.c: Destroying worker thread 7 [2018-09-05 09:33:15] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 192.168.128.134:19151 [2018-09-05 09:33:19] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19755 [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: inv_session 0x7f94bc46a188 has no ast session [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:33:19] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:21] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 192.168.128.134:19151 [2018-09-05 09:33:24] DEBUG[20961][C-00000002] res_rtp_asterisk.c: Got RTCP report of 84 bytes from 192.168.128.134:19755 [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The state change pertains to the endpoint '(PJSIP/-00000005)' [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: Source of transaction state change is TIMER [2018-09-05 09:33:24] DEBUG[20841] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge_channel.c: Setting 0x7f948c013798(PJSIP/-00000005) state from:0 to:1 [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: pulling 0x7f948c013798(PJSIP/-00000005) [2018-09-05 09:33:24] VERBOSE[20969][C-00000002] bridge_channel.c: Channel PJSIP/-00000005 left 'simple_bridge' basic-bridge <771dc477-b011-416b-af1a-7e8fb22be7de> [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c013798(PJSIP/-00000005) is leaving simple_bridge technology [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: dissolving bridge with cause 16(Normal Clearing) [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge_channel.c: Setting 0x7f948c011798(PJSIP/cucm-00000003) state from:0 to:2 [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: queueing action type:13 sub:1001 [2018-09-05 09:33:24] DEBUG[20860] cdr.c: Finalized CDR for PJSIP/cucm-00000003 - start 1536157967.379909 answer 1536157972.970348 end 1536158004.972910 dispo ANSWERED [2018-09-05 09:33:24] DEBUG[20969][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de is dissolved, not performing smart bridge operation. [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: pulling 0x7f948c011798(PJSIP/cucm-00000003) [2018-09-05 09:33:24] DEBUG[20969][C-00000002] channel.c: Channel 0x7f948c00ddd8 'PJSIP/-00000005' hanging up. Refs: 2 [2018-09-05 09:33:24] DEBUG[20969][C-00000002] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [2018-09-05 09:33:24] DEBUG[20969][C-00000002] channel.c: Channel 0x7f948c00ddd8 'PJSIP/-00000005' destroying [2018-09-05 09:33:24] DEBUG[20860] cdr.c: CDR for PJSIP/-00000005 is dialed and has no Party B; discarding [2018-09-05 09:33:24] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - [2018-09-05 09:33:24] DEBUG[20852] devicestate.c: Changing state for PJSIP/ - state 1 (Not in use) [2018-09-05 09:33:24] DEBUG[20894] app_queue.c: Device 'PJSIP/' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-09-05 09:33:24] DEBUG[20864] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '64.9.242.108' [2018-09-05 09:33:24] DEBUG[20864] res_pjsip/pjsip_resolver.c: Transport type for target '64.9.242.108' is 'TLS' [2018-09-05 09:33:24] DEBUG[20864] res_pjsip/pjsip_resolver.c: Target '64.9.242.108' is an IP address, skipping resolution [2018-09-05 09:33:24] VERBOSE[20864] res_pjsip_logger.c: <--- Transmitting SIP request (715 bytes) to TLS:64.9.242.108:5061 ---> BYE sip:@AAZZHPMX3VB23TAQKNTY2NJRGSWCDQCQ5KQVTLVU6LDTUHUDAGTXPY3JBDEB7PX:5060;transport=udp;uri-econt=DRM3ITQP5GXTVTUBQORYO2VIRBURQ SIP/2.0 Via: SIP/2.0/TLS 192.168.128.7:5061;rport;branch=z9hG4bKPjb9c15165-6e78-44eb-8c41-5f3a53266081;alias From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 To: @obihai.sip.google.com>;tag=1761696072 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8013 BYE Route: Route: Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The state change pertains to the endpoint '()' [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f94bc4596b8) [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc45a5c8 [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The current transaction state is Calling [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The state change pertains to the endpoint '()' [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f94bc4596b8 [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:33:24] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Destroying SIP session with endpoint [2018-09-05 09:33:24] DEBUG[20865] rtp_engine.c: Destroyed RTP instance '0x7f94bc4645a8' [2018-09-05 09:33:24] VERBOSE[20961][C-00000002] bridge_channel.c: Channel PJSIP/cucm-00000003 left 'simple_bridge' basic-bridge <771dc477-b011-416b-af1a-7e8fb22be7de> [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge_channel.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: 0x7f948c011798(PJSIP/cucm-00000003) is leaving simple_bridge technology [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de is dissolved, not performing smart bridge operation. [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: actually destroying basic bridge, nobody wants it anymore [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: calling basic bridge destructor [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: calling simple_bridge technology stop [2018-09-05 09:33:24] DEBUG[20961][C-00000002] bridge.c: Bridge 771dc477-b011-416b-af1a-7e8fb22be7de: calling simple_bridge technology destructor [2018-09-05 09:33:24] DEBUG[20961][C-00000002] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2018-09-05 09:33:24] DEBUG[20961][C-00000002] pbx.c: Spawn extension (dialprovider,s-CHANUNAVAIL,1) exited non-zero on 'PJSIP/cucm-00000003' [2018-09-05 09:33:24] VERBOSE[20961][C-00000002] pbx.c: Spawn extension (dialprovider, s-CHANUNAVAIL, 1) exited non-zero on 'PJSIP/cucm-00000003' [2018-09-05 09:33:24] DEBUG[20961][C-00000002] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/cucm-00000003' [2018-09-05 09:33:24] DEBUG[20961][C-00000002] channel.c: Channel 0x7f94bc46d628 'PJSIP/cucm-00000003' hanging up. Refs: 2 [2018-09-05 09:33:24] DEBUG[20961][C-00000002] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [2018-09-05 09:33:24] DEBUG[20865] rtp_engine.c: Destroyed RTP instance '0x7f94bc4662f8' [2018-09-05 09:33:24] DEBUG[20865] rtp_engine.c: Destroyed RTP instance '0x7f94bc46bde8' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Method is BYE [2018-09-05 09:33:24] DEBUG[20865] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.128.12' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.128.12' is 'UDP' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip/pjsip_resolver.c: Target '192.168.128.12' is an IP address, skipping resolution [2018-09-05 09:33:24] DEBUG[20865] netsock2.c: Splitting '192.168.128.12' into... [2018-09-05 09:33:24] DEBUG[20865] netsock2.c: ...host '192.168.128.12' and port ''. [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation [2018-09-05 09:33:24] VERBOSE[20865] res_pjsip_logger.c: <--- Transmitting SIP request (524 bytes) to UDP:192.168.128.12:5060 ---> BYE sip:@192.168.128.12:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.128.7:5060;rport;branch=z9hG4bKPj9de1cb75-56ae-4964-b618-dc347ec6bb97 From: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 To: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 CSeq: 6315 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-b300c563e8 Content-Length: 0 [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm(PJSIP/cucm-00000003)' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The current transaction state is Calling [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The transaction state change event is TX_MSG [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The current inv state is CONFIRMED [2018-09-05 09:33:24] DEBUG[20961][C-00000002] channel.c: Channel 0x7f94bc46d628 'PJSIP/cucm-00000003' destroying [2018-09-05 09:33:24] DEBUG[20852] devicestate.c: No provider found, checking channel drivers for PJSIP - cucm [2018-09-05 09:33:24] DEBUG[20852] devicestate.c: Changing state for PJSIP/cucm - state 1 (Not in use) [2018-09-05 09:33:24] DEBUG[20894] app_queue.c: Device 'PJSIP/cucm' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2018-09-05 09:33:24] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (469 bytes) from UDP:192.168.128.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.128.7:5060;rport;branch=z9hG4bKPj9de1cb75-56ae-4964-b618-dc347ec6bb97 From: @mydomain.com>;tag=c25710da-f277-42f5-9005-7e0676e25e15 To: "My Name" @mydomain.com>;tag=434384~58340c4c-2bc2-48dc-96bc-4e4d906b83a8-26693964 Date: Wed, 05 Sep 2018 14:33:24 GMT Call-ID: 8db49700-b8f1e90f-35f77-c80a8c0@192.168.128.12 Server: Cisco-CP-DX650/10.2.5 CSeq: 6315 BYE Content-Length: 0 [2018-09-05 09:33:24] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94c0019278 for Response msg 200/BYE/cseq=6315 (rdata0x7f94b000b278) [2018-09-05 09:33:24] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003e associated with dialog dlg0x7f94c0019278 [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: There is no transaction involved in this state change [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Source of transaction state change is RX_MSG [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Response is 200 OK [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The current transaction state is Completed [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Received response [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: Response is 200 OK [2018-09-05 09:33:24] DEBUG[20865] res_pjsip_session.c: BYE received final response code 200 [2018-09-05 09:33:25] VERBOSE[20864] res_pjsip_logger.c: <--- Received SIP response (596 bytes) from TLS:64.9.242.108:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.128.7:5061;rport=45477;branch=z9hG4bKPjb9c15165-6e78-44eb-8c41-5f3a53266081;received=;alias Record-Route: Record-Route: To: @obihai.sip.google.com>;tag=1761696072 From: @192.168.128.7>;tag=82f9b9ed-e0e9-4396-81bf-7aa12cb54450 Call-ID: 6bb21325-f683-4e07-8971-0923c7ea4f1d CSeq: 8013 BYE Allow: ACK, BYE, CANCEL, INVITE, UPDATE Content-Length: 0 [2018-09-05 09:33:25] DEBUG[20864] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f94bc42b938 for Response msg 200/BYE/cseq=8013 (rdata0x7f94bc41fdc0) [2018-09-05 09:33:25] DEBUG[20864] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/BYE/cseq=8013 (rdata0x7f94bc41fdc0). Using request transaction as basis. [2018-09-05 09:33:25] DEBUG[20864] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7f94bc45a5c8 for Response msg 200/BYE/cseq=8013 (rdata0x7f94bc41fdc0). [2018-09-05 09:33:25] DEBUG[20864] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002d to use for Response msg 200/BYE/cseq=8013 (rdata0x7f94bc41fdc0) [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: inv_session 0x7f94bc470738 has no ast session [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc45a5c8 [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: The current transaction state is Completed [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: The transaction state change event is RX_MSG [2018-09-05 09:33:25] DEBUG[20865] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: inv_session 0x7f94bc470738 has no ast session [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc45a5c8 [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:33:25] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The state change pertains to the endpoint 'cucm()' [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f94bc461c58 [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The current transaction state is Terminated [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The transaction state change event is TIMER [2018-09-05 09:33:29] DEBUG[20864] res_pjsip_session.c: The current inv state is DISCONNCTD [2018-09-05 09:33:29] DEBUG[20865] res_pjsip_session.c: Destroying SIP session with endpoint cucm [2018-09-05 09:33:36] DEBUG[20875] res_pjsip_registrar.c: Woke up at 1536158016 Interval: 30 [2018-09-05 09:33:36] DEBUG[20875] res_pjsip_registrar.c: Expiring 0 contacts [2018-09-05 09:33:44] DEBUG[20989] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:44] DEBUG[20841] threadpool.c: Destroying worker thread 16 [2018-09-05 09:33:47] DEBUG[20866] threadpool.c: Worker thread idle timeout reached. Dying. [2018-09-05 09:33:47] DEBUG[20862] threadpool.c: Destroying worker thread 6