[Feb 28 10:39:13] Asterisk 16.2.0 built by root @ ast-node3a.rgs.ru on a x86_64 running Linux on 2019-02-27 13:24:16 UTC [Feb 28 10:39:22] DEBUG[22874] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:39:22] DEBUG[22872] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:39:22] DEBUG[22873] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:39:22] DEBUG[22868] threadpool.c: Destroying worker thread 4 [Feb 28 10:39:22] DEBUG[22868] threadpool.c: Destroying worker thread 2 [Feb 28 10:39:22] DEBUG[22868] threadpool.c: Destroying worker thread 3 [Feb 28 10:39:22] DEBUG[22870] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:39:22] DEBUG[22871] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:39:22] DEBUG[22868] threadpool.c: Destroying worker thread 0 [Feb 28 10:39:22] DEBUG[22868] threadpool.c: Destroying worker thread 1 [Feb 28 10:39:32] DEBUG[22902] res_pjsip_registrar.c: Woke up at 1551339572 Interval: 30 [Feb 28 10:39:32] DEBUG[22902] res_pjsip_registrar.c: Expiring 0 contacts [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (915 bytes) from UDP:10.199.251.2:5060 ---> INVITE sip:0986010@10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK1783727610 From: "0986011" ;tag=4127690886 To: Call-ID: 1_2384255746@10.199.251.2 CSeq: 1 INVITE Contact: Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T42G 29.83.0.35 Allow-Events: talk,hold,conference,refer,check-sync Supported: replaces Content-Length: 306 v=0 o=- 20186 20186 IN IP4 10.199.251.2 s=SDP data c=IN IP4 10.199.251.2 t=0 0 m=audio 12446 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000025 to use for Request msg INVITE/cseq=1 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Pub' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub1' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub2' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Identified by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0986011'. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (484 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK1783727610 Call-ID: 1_2384255746@10.199.251.2 From: "0986011" ;tag=4127690886 To: ;tag=z9hG4bK1783727610 CSeq: 1 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1551339583/44cfb8672bf78692af47ea77c03344a8",opaque="5ac039472900d923",algorithm=md5,qop="auth" Server: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (290 bytes) from UDP:10.199.251.2:5060 ---> ACK sip:0986010@10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK1783727610 From: "0986011" ;tag=4127690886 To: ;tag=z9hG4bK1783727610 Call-ID: 1_2384255746@10.199.251.2 CSeq: 1 ACK Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000025 to use for Request msg ACK/cseq=1 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Pub' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub1' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub2' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Identified by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (1195 bytes) from UDP:10.199.251.2:5060 ---> INVITE sip:0986010@10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK3622178565 From: "0986011" ;tag=4127690886 To: Call-ID: 1_2384255746@10.199.251.2 CSeq: 2 INVITE Contact: Authorization: Digest username="0986011", realm="asterisk", nonce="1551339583/44cfb8672bf78692af47ea77c03344a8", uri="sip:0986010@10.200.32.222:5060", response="e9541eaba8000a69fb19df53d6129a64", algorithm=MD5, cnonce="0a4f113b", opaque="5ac039472900d923", qop=auth, nc=00000001 Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T42G 29.83.0.35 Allow-Events: talk,hold,conference,refer,check-sync Supported: replaces Content-Length: 306 v=0 o=- 20186 20186 IN IP4 10.199.251.2 s=SDP data c=IN IP4 10.199.251.2 t=0 0 m=audio 12446 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000025 to use for Request msg INVITE/cseq=2 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Pub' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub1' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub2' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Identified by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0986011'. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_authenticator_digest.c: Calculated nonce 1551339583/44cfb8672bf78692af47ea77c03344a8. Actual nonce is 1551339583/44cfb8672bf78692af47ea77c03344a8 [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000025 to use for Request msg INVITE/cseq=2 (rdata0x7fa06c00c3a8) [Feb 28 10:39:43] DEBUG[22893] pbx_lua.c: Looking up 0986010@out_context:1 [Feb 28 10:39:43] VERBOSE[22893] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '10.200.32.222' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (310 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK3622178565 Call-ID: 1_2384255746@10.199.251.2 From: "0986011" ;tag=4127690886 To: CSeq: 2 INVITE Server: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011()' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is INCOMING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011()' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is INCOMING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 10.200.32.222: Using it for RTP media. [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa0c4026390' [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Allocated port 15272 for RTP instance '0x7fa0c4026390' [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Creating ICE session 10.200.32.222:15272 (15272) for RTP instance '0x7fa0c4026390' [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: RTP instance '0x7fa0c4026390' is setup and ready to go [Feb 28 10:39:43] DEBUG[22893] acl.c: Attached to given IP address [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa0c4026390' [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7fa0c4028408) from 0x7fa0e87242f0 to 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7fa0c401b818) from 0x7fa0e87242f0 to 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7fa0c40051e8) from 0x7fa0e87242f0 to 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7fa0c40108d8) from 0x7fa0e87242f0 to 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7fa0c4010888) from 0x7fa0e87242f0 to 0x7fa0e87242f0 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying rx payload mapping 0 (0x7fa0c4028408) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying rx payload mapping 8 (0x7fa0c401b818) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying rx payload mapping 9 (0x7fa0c40051e8) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying rx payload mapping 18 (0x7fa0c40108d8) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying rx payload mapping 101 (0x7fa0c4010888) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 0 (0x7fa0c4028408) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 8 (0x7fa0c401b818) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 9 (0x7fa0c40051e8) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 18 (0x7fa0c40108d8) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 101 (0x7fa0c4010888) from 0x7fa0e87242f0 to 0x7fa0c4026568 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Media stream 'audio' handled by audio [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fa0c4026390' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE [Feb 28 10:39:43] DEBUG[22893] channel.c: Channel 0x7fa0c402b1b0 'PJSIP/0986011-00000000' allocated [Feb 28 10:39:43] DEBUG[22893] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/0986011-00000000 [Feb 28 10:39:43] DEBUG[23008][C-00000001] pbx_lua.c: Looking up 0986010@out_context:1 [Feb 28 10:39:43] DEBUG[23008][C-00000001] pbx_lua.c: Looking up 0986010@out_context:1 [Feb 28 10:39:43] VERBOSE[23008][C-00000001] pbx_lua.c: Executing [0986010@out_context:1] dial("PJSIP/0986011-00000000", "PJSIP/0986010") [Feb 28 10:39:43] DEBUG[22893] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel 0x7fa13c00c860 'PJSIP/0986010-00000001' allocated [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 10.200.32.222: Using it for RTP media. [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa0c4032200' [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Allocated port 15190 for RTP instance '0x7fa0c4032200' [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Creating ICE session 10.200.32.222:15190 (15190) for RTP instance '0x7fa0c4032200' [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: RTP instance '0x7fa0c4032200' is setup and ready to go [Feb 28 10:39:43] DEBUG[22893] acl.c: Attached to given IP address [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa0c4032200' [Feb 28 10:39:43] VERBOSE[23008][C-00000001] app_dial.c: Called PJSIP/0986010 [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986010-00000001 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting write format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986010-00000001 setting write format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: PJSIP/0986011-00000000: Dropping redundant connected line update "Test" <0986010>. [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.199.140.233' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.199.140.233' is 'UDP' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.199.140.233' is an IP address, skipping resolution [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (969 bytes) to UDP:10.199.140.233:5060 ---> INVITE sip:0986010@10.199.140.233:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj29a062fb-9612-42d0-909c-6f5365ef0d2c From: "Test" ;tag=b051147f-e3f6-4efc-9ca1-9256c66438a6 To: Contact: Call-ID: aec386bb-cb92-4eae-81d4-86d534631629 CSeq: 13199 INVITE Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 P-Asserted-Identity: "Test" Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Type: application/sdp Content-Length: 239 v=0 o=- 1052454668 1052454668 IN IP4 10.200.32.222 s=Asterisk c=IN IP4 10.200.32.222 t=0 0 m=audio 15190 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986010(PJSIP/0986010-00000001)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c4039e18) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986010(PJSIP/0986010-00000001)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c4039e18) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c4039e18 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Calling [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (370 bytes) from UDP:10.199.140.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPj29a062fb-9612-42d0-909c-6f5365ef0d2c From: "Test" ;tag=b051147f-e3f6-4efc-9ca1-9256c66438a6 To: Call-ID: aec386bb-cb92-4eae-81d4-86d534631629 CSeq: 13199 INVITE User-Agent: Yealink SIP-T19P_E2 53.84.0.10 Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c400db18 for Response msg 100/INVITE/cseq=13199 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986010-0000005e associated with dialog dlg0x7fa0c400db18 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986010(PJSIP/0986010-00000001)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c4039e18) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c4039e18 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 100 Trying [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (500 bytes) from UDP:10.199.140.233:5060 ---> SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPj29a062fb-9612-42d0-909c-6f5365ef0d2c From: "Test" ;tag=b051147f-e3f6-4efc-9ca1-9256c66438a6 To: ;tag=657748006 Call-ID: aec386bb-cb92-4eae-81d4-86d534631629 CSeq: 13199 INVITE Contact: User-Agent: Yealink SIP-T19P_E2 53.84.0.10 Diversion: ;reason=unconditional Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c400db18 for Response msg 302/INVITE/cseq=13199 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986010-0000005e associated with dialog dlg0x7fa0c400db18 [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (409 bytes) to UDP:10.199.140.233:5060 ---> ACK sip:0986010@10.199.140.233:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj29a062fb-9612-42d0-909c-6f5365ef0d2c From: "Test" ;tag=b051147f-e3f6-4efc-9ca1-9256c66438a6 To: ;tag=657748006 Call-ID: aec386bb-cb92-4eae-81d4-86d534631629 CSeq: 13199 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 302 Moved Temporarily [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986010(PJSIP/0986010-00000001)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c4039e18) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 302 Moved Temporarily [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986010(PJSIP/0986010-00000001)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c4039e18) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c4039e18 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Completed [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:43] VERBOSE[23008][C-00000001] app_dial.c: Now forwarding PJSIP/0986011-00000000 to 'Local/0986012@out_context' (thanks to PJSIP/0986010-00000001) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel 0x7fa13c012520 'Local/0986012@out_context-00000000;1' allocated [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel 0x7fa13c015b10 'Local/0986012@out_context-00000000;2' allocated [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting write format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting write format path: alaw -> alaw [Feb 28 10:39:43] NOTICE[23008][C-00000001] app_dial.c: Not accepting call completion offers from call-forward recipient Local/0986012@out_context-00000000;1 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE, Response is 181 Call Is Being Forwarded [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (632 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 181 Call Is Being Forwarded Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK3622178565 Call-ID: 1_2384255746@10.199.251.2 From: "0986011" ;tag=4127690886 To: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c CSeq: 2 INVITE Server: Asterisk PBX 16.2.0 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER P-Asserted-Identity: "Test" Diversion: ;reason=unconditional Content-Length: 0 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:43] DEBUG[23008][C-00000001] pbx_lua.c: Looking up 0986012@out_context:1 [Feb 28 10:39:43] DEBUG[23008][C-00000001] channel.c: Channel 0x7fa13c00c860 'PJSIP/0986010-00000001' hanging up. Refs: 2 [Feb 28 10:39:43] DEBUG[23008][C-00000001] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Feb 28 10:39:43] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986011-00000000 - start 1551339583.071809 answer 0.000000 end 1551339583.146373 dispo NO ANSWER [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Destroying SIP session with endpoint 0986010 [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Destroyed RTP instance '0x7fa0c4032200' [Feb 28 10:39:43] DEBUG[22893] channel.c: Channel 0x7fa13c00c860 'PJSIP/0986010-00000001' destroying [Feb 28 10:39:43] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986010-00000001 - start 1551339583.074972 answer 0.000000 end 1551339583.146522 dispo FAILED [Feb 28 10:39:43] DEBUG[22888] cdr.c: CDR for PJSIP/0986010-00000001 is dialed and has no Party B; discarding [Feb 28 10:39:43] DEBUG[22868] threadpool.c: Increasing threadpool stasis-core's size by 1 [Feb 28 10:39:43] DEBUG[23010][C-00000001] pbx_lua.c: Looking up 0986012@out_context:1 [Feb 28 10:39:43] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986010 [Feb 28 10:39:43] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986010 - state 1 (Not in use) [Feb 28 10:39:43] DEBUG[23010][C-00000001] pbx_lua.c: Looking up 0986012@out_context:1 [Feb 28 10:39:43] VERBOSE[23010][C-00000001] pbx_lua.c: Executing [0986012@out_context:1] dial("Local/0986012@out_context-00000000;2", "PJSIP/0986012") [Feb 28 10:39:43] DEBUG[22893] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Feb 28 10:39:43] DEBUG[22893] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Channel 0x7fa14000c7c0 'PJSIP/0986012-00000002' allocated [Feb 28 10:39:43] DEBUG[23010][C-00000001] rtp_engine.c: Can't find native functions for channel 'Local/0986012@out_context-00000000;2' [Feb 28 10:39:43] VERBOSE[23010][C-00000001] app_dial.c: Called PJSIP/0986012 [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 10.200.32.222: Using it for RTP media. [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa0c40325a0' [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting write format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting read format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting write format path: alaw -> alaw [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Allocated port 11880 for RTP instance '0x7fa0c40325a0' [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Creating ICE session 10.200.32.222:11880 (11880) for RTP instance '0x7fa0c40325a0' [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.118' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.118' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:43] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:43] DEBUG[22893] rtp_engine.c: RTP instance '0x7fa0c40325a0' is setup and ready to go [Feb 28 10:39:43] DEBUG[22893] acl.c: Attached to given IP address [Feb 28 10:39:43] DEBUG[22893] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa0c40325a0' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE [Feb 28 10:39:43] DEBUG[23010][C-00000001] channel.c: Local/0986012@out_context-00000000;2: Dropping redundant connected line update "Test" <0986012>. [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.199.48.8' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.199.48.8' is 'UDP' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.199.48.8' is an IP address, skipping resolution [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (1021 bytes) to UDP:10.199.48.8:5060 ---> INVITE sip:0986012@10.199.48.8:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPjaef6abf9-a79e-4fd9-adfa-3aec0aa6b084 From: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 To: Contact: Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 4684 INVITE Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 P-Asserted-Identity: "Test" Diversion: ;reason=unconditional Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Type: application/sdp Content-Length: 237 v=0 o=- 277001839 277001839 IN IP4 10.200.32.222 s=Asterisk c=IN IP4 10.200.32.222 t=0 0 m=audio 11880 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c403f738 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Calling [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (440 bytes) from UDP:10.199.48.8:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPjaef6abf9-a79e-4fd9-adfa-3aec0aa6b084 From: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 To: Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 4684 INVITE Allow: INVITE, ACK, BYE, CANCEL, INFO, MESSAGE, NOTIFY, OPTIONS, REFER, UPDATE, PRACK Server: SIPPER for PhonerLite Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c40110a8 for Response msg 100/INVITE/cseq=4684 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986012-0000005f associated with dialog dlg0x7fa0c40110a8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c403f738 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is CALLING [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 100 Trying [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR 'CUCM8_Sub1' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying contact 'CUCM8_Sub1@@32eab8363cd59927b3fea2f008bdd179' on AOR 'CUCM8_Sub1' [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: Wrapper created [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: Set timer to 3000 msec [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.77.1.108' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.77.1.108' is 'UDP' [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.77.1.108' is an IP address, skipping resolution [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (423 bytes) to UDP:10.77.1.108:5060 ---> OPTIONS sip:10.77.1.108:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj36e49d0c-18f0-4ff9-b1bb-cc9fa3966b18 From: ;tag=6cb2fc12-baeb-4093-b349-9173b7286758 To: Contact: Call-ID: a4794407-28b7-47bb-be3e-836b95ef069c CSeq: 38215 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (442 bytes) from UDP:10.77.1.108:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj36e49d0c-18f0-4ff9-b1bb-cc9fa3966b18 From: ;tag=6cb2fc12-baeb-4093-b349-9173b7286758 To: ;tag=46284817 Date: Thu, 28 Feb 2019 07:39:43 GMT Call-ID: a4794407-28b7-47bb-be3e-836b95ef069c CSeq: 38215 OPTIONS Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=38215 (rdata0x7fa06c0008e8). Using request transaction as basis. [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa0c4042cd8 for Response msg 200/OPTIONS/cseq=38215 (rdata0x7fa06c0008e8). [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/CUCM8_Sub1-0000003f on transaction tsx0x7fa0c4042cd8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: PJSIP tsx response received [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: Cancelling timer [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: Timer cancelled [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: Callbacks executed [Feb 28 10:39:43] DEBUG[22893] res_pjsip.c: 0x7fa0c402dac0: wrapper destroyed [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_options.c: Endpoint state compositor 'CUCM8_Sub1' is online as AOR 'CUCM8_Sub1' is available [Feb 28 10:39:43] VERBOSE[22893] res_pjsip/pjsip_configuration.c: Endpoint CUCM8_Sub1 is now Reachable [Feb 28 10:39:43] VERBOSE[22893] res_pjsip/pjsip_options.c: Contact CUCM8_Sub1/sip:10.77.1.108:5060 is now Reachable. RTT: 1.683 msec [Feb 28 10:39:43] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - CUCM8_Sub1 [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_options.c: AOR 'CUCM8_Sub1' now has 1 available contacts [Feb 28 10:39:43] DEBUG[22880] devicestate.c: Changing state for PJSIP/CUCM8_Sub1 - state 1 (Not in use) [Feb 28 10:39:43] DEBUG[22916] app_queue.c: Device 'PJSIP/CUCM8_Sub1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:43] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (607 bytes) from UDP:10.199.48.8:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPjaef6abf9-a79e-4fd9-adfa-3aec0aa6b084 From: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 To: ;tag=0033caad9939e91198b231367a0894f6 Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 4684 INVITE Contact: Allow: INVITE, ACK, BYE, CANCEL, INFO, MESSAGE, NOTIFY, OPTIONS, REFER, UPDATE, PRACK Supported: 100rel, replaces, from-change, gruu Server: SIPPER for PhonerLite Content-Length: 0 [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c40110a8 for Response msg 180/INVITE/cseq=4684 (rdata0x7fa06c0008e8) [Feb 28 10:39:43] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986012-0000005f associated with dialog dlg0x7fa0c40110a8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 180 Ringing [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c403f738 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:43] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986012 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Response is 180 Ringing [Feb 28 10:39:43] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986012 - state 6 (Ringing) [Feb 28 10:39:43] VERBOSE[23010][C-00000001] app_dial.c: PJSIP/0986012-00000002 is ringing [Feb 28 10:39:43] DEBUG[22916] app_queue.c: Device 'PJSIP/0986012' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 28 10:39:43] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for Local - 0986012@out_context [Feb 28 10:39:43] VERBOSE[23008][C-00000001] app_dial.c: Local/0986012@out_context-00000000;1 is ringing [Feb 28 10:39:43] DEBUG[22880] devicestate.c: Changing state for Local/0986012@out_context - state 2 (In use) [Feb 28 10:39:43] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986011 [Feb 28 10:39:43] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986011 - state 2 (In use) [Feb 28 10:39:43] DEBUG[22916] app_queue.c: Device 'Local/0986012@out_context' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 10:39:43] DEBUG[22916] app_queue.c: Device 'PJSIP/0986011' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 10:39:43] VERBOSE[23010][C-00000001] app_dial.c: PJSIP/0986012-00000002 is ringing [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Feb 28 10:39:43] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:43] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (616 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK3622178565 Call-ID: 1_2384255746@10.199.251.2 From: "0986011" ;tag=4127690886 To: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c CSeq: 2 INVITE Server: Asterisk PBX 16.2.0 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Diversion: ;reason=unconditional Contact: P-Asserted-Identity: "Test" Content-Length: 0 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current transaction state is Proceeding [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:43] DEBUG[22893] res_pjsip_session.c: The current inv state is EARLY [Feb 28 10:39:45] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (909 bytes) from UDP:10.199.48.8:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPjaef6abf9-a79e-4fd9-adfa-3aec0aa6b084 From: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 To: ;tag=0033caad9939e91198b231367a0894f6 Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 4684 INVITE Contact: Content-Type: application/sdp Allow: INVITE, ACK, BYE, CANCEL, INFO, MESSAGE, NOTIFY, OPTIONS, REFER, UPDATE, PRACK Session-Expires: 1800;refresher=uac Supported: 100rel, replaces, from-change, gruu, timer Server: SIPPER for PhonerLite Content-Length: 228 v=0 o=- 280902621 1 IN IP4 10.199.48.8 s=SIPPER for PhonerLite c=IN IP4 10.199.48.8 t=0 0 m=audio 5062 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ssrc:2489749426 a=sendrecv [Feb 28 10:39:45] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c40110a8 for Response msg 200/INVITE/cseq=4684 (rdata0x7fa06c0008e8) [Feb 28 10:39:45] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986012-0000005f associated with dialog dlg0x7fa0c40110a8 [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current inv state is CONNECTING [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Response is 200 OK [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Feb 28 10:39:45] VERBOSE[23010][C-00000001] app_dial.c: PJSIP/0986012-00000002 answered Local/0986012@out_context-00000000;2 [Feb 28 10:39:45] DEBUG[22893] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fa0c40325a0' [Feb 28 10:39:45] DEBUG[22893] netsock2.c: Splitting '10.199.48.8' into... [Feb 28 10:39:45] DEBUG[22893] netsock2.c: ...host '10.199.48.8' and port ''. [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986012 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986012 - state 2 (In use) [Feb 28 10:39:45] DEBUG[22893] acl.c: For destination '10.199.48.8', our source address is '10.200.32.118'. [Feb 28 10:39:45] DEBUG[22893] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa0c40325a0' [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting read format path: alaw -> alaw [Feb 28 10:39:45] VERBOSE[22893] res_rtp_asterisk.c: 0x7fa0c403a790 -- Strict RTP learning after remote address set to: 10.199.48.8:5062 [Feb 28 10:39:45] DEBUG[22916] app_queue.c: Device 'PJSIP/0986012' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22893] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fa0e8723f70 [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 8 (0x7fa0c4041b28) from 0x7fa0e8723f70 to 0x7fa0c4032778 [Feb 28 10:39:45] DEBUG[22893] rtp_engine.c: Copying tx payload mapping 101 (0x7fa0c4032328) from 0x7fa0e8723f70 to 0x7fa0c4032778 [Feb 28 10:39:45] DEBUG[22893] channel.c: Channel PJSIP/0986012-00000002 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22893] channel.c: Channel PJSIP/0986012-00000002 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Feb 28 10:39:45] DEBUG[23010][C-00000001] core_unreal.c: Blocked indication -1 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for Local - 0986012@out_context [Feb 28 10:39:45] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.199.48.8' [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for Local/0986012@out_context - state 2 (In use) [Feb 28 10:39:45] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.199.48.8' is 'UDP' [Feb 28 10:39:45] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.199.48.8' is an IP address, skipping resolution [Feb 28 10:39:45] VERBOSE[23008][C-00000001] app_dial.c: Local/0986012@out_context-00000000;1 answered PJSIP/0986011-00000000 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for Local - 0986012@out_context [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for Local/0986012@out_context - state 2 (In use) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge 'ac48b971-a755-4b2e-9417-0739bce5ba0e' can not use native RTP bridge as two channels are required [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: calling simple_bridge technology constructor [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: calling simple_bridge technology start [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22916] app_queue.c: Device 'Local/0986012@out_context' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 10:39:45] DEBUG[22916] app_queue.c: Device 'Local/0986012@out_context' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting write format path: alaw -> alaw [Feb 28 10:39:45] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (465 bytes) to UDP:10.199.48.8:5060 ---> ACK sip:0986012@10.199.48.8:5060;gr=80114F03-9339-E911-9878-31367A0894F6 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj9cb1025d-c7c3-49b9-880a-b229759806a7 From: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 To: ;tag=0033caad9939e91198b231367a0894f6 Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 4684 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986011 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986011 - state 2 (In use) [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c403f738) [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fa0c403f738 [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current transaction state is Terminated [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Feb 28 10:39:45] DEBUG[22894] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fa0c4026390' [Feb 28 10:39:45] DEBUG[22894] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 28 10:39:45] DEBUG[22894] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Response is 200 OK [Feb 28 10:39:45] DEBUG[22894] acl.c: For destination '10.199.251.2', our source address is '10.200.32.118'. [Feb 28 10:39:45] DEBUG[22894] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa0c4026390' [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa1400105c0(PJSIP/0986012-00000002) is joining [Feb 28 10:39:45] VERBOSE[22894] res_rtp_asterisk.c: 0x7fa0c4011a50 -- Strict RTP learning after remote address set to: 10.199.251.2:12446 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7fa0e86a71e0 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fa0e86a71e0 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fa0e86a71e0 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fa0e86a71e0 [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: pushing 0x7fa1400105c0(PJSIP/0986012-00000002) [Feb 28 10:39:45] VERBOSE[23013][C-00000001] bridge_channel.c: Channel PJSIP/0986012-00000002 joined 'simple_bridge' basic-bridge [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Copying tx payload mapping 0 (0x7fa0bc011568) from 0x7fa0e86a71e0 to 0x7fa0c4026568 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Copying tx payload mapping 8 (0x7fa0bc00e1c8) from 0x7fa0e86a71e0 to 0x7fa0c4026568 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Copying tx payload mapping 9 (0x7fa0bc010ff8) from 0x7fa0e86a71e0 to 0x7fa0c4026568 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Copying tx payload mapping 18 (0x7fa0bc00e298) from 0x7fa0e86a71e0 to 0x7fa0c4026568 [Feb 28 10:39:45] DEBUG[22894] rtp_engine.c: Copying tx payload mapping 101 (0x7fa0bc00e248) from 0x7fa0e86a71e0 to 0x7fa0c4026568 [Feb 28 10:39:45] DEBUG[22894] channel.c: Channel PJSIP/0986011-00000000 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge_native_rtp.c: Bridge 'ac48b971-a755-4b2e-9417-0739bce5ba0e' can not use native RTP bridge as two channels are required [Feb 28 10:39:45] DEBUG[22894] channel.c: Channel PJSIP/0986011-00000000 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e is already using the new technology. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa1400105c0(PJSIP/0986012-00000002) is joining simple_bridge technology [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Feb 28 10:39:45] DEBUG[22894] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa140010910(Local/0986012@out_context-00000000;2) is joining [Feb 28 10:39:45] DEBUG[23013][C-00000001] channel.c: Dropping duplicate answer! [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: pushing 0x7fa140010910(Local/0986012@out_context-00000000;2) [Feb 28 10:39:45] VERBOSE[22894] res_pjsip_logger.c: <--- Transmitting SIP response (922 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK3622178565 Call-ID: 1_2384255746@10.199.251.2 From: "0986011" ;tag=4127690886 To: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c CSeq: 2 INVITE Server: Asterisk PBX 16.2.0 Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_channel.c: Channel Local/0986012@out_context-00000000;2 joined 'simple_bridge' basic-bridge [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge 'ac48b971-a755-4b2e-9417-0739bce5ba0e'. Checking compatability for channels 'PJSIP/0986012-00000002' and 'Local/0986012@out_context-00000000;2' [Feb 28 10:39:45] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986012-00000002 - start 1551339583.149378 answer 1551339585.075553 end 1551339585.076206 dispo ANSWERED [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge 'ac48b971-a755-4b2e-9417-0739bce5ba0e' can not use native RTP bridge as could not get details [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The current inv state is CONNECTING [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Source of transaction state change is TX_MSG [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e is already using the new technology. [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa140010910(Local/0986012@out_context-00000000;2) is joining simple_bridge technology [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa0c40267b8) [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The current transaction state is Completed [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:45] DEBUG[22894] res_pjsip_session.c: The current inv state is CONNECTING [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel PJSIP/0986012-00000002 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;2 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f' can not use native RTP bridge as two channels are required [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling simple_bridge technology constructor [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling simple_bridge technology start [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c017e50(Local/0986012@out_context-00000000;1) is joining [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pushing 0x7fa13c017e50(Local/0986012@out_context-00000000;1) [Feb 28 10:39:45] VERBOSE[23014][C-00000001] bridge_channel.c: Channel Local/0986012@out_context-00000000;1 joined 'simple_bridge' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f' can not use native RTP bridge as two channels are required [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is already using the new technology. [Feb 28 10:39:45] DEBUG[23014][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c017e50(Local/0986012@out_context-00000000;1) is joining simple_bridge technology [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c015470(PJSIP/0986011-00000000) is joining [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pushing 0x7fa13c015470(PJSIP/0986011-00000000) [Feb 28 10:39:45] VERBOSE[23008][C-00000001] bridge_channel.c: Channel PJSIP/0986011-00000000 joined 'simple_bridge' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Checking compatability for channels 'Local/0986012@out_context-00000000;1' and 'PJSIP/0986011-00000000' [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f' can not use native RTP bridge as could not get details [Feb 28 10:39:45] DEBUG[22888] cdr.c: Finalized CDR for Local/0986012@out_context-00000000;1 - start 1551339583.145807 answer 1551339585.075790 end 1551339585.076573 dispo ANSWERED [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is already using the new technology. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c015470(PJSIP/0986011-00000000) is joining simple_bridge technology [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel Local/0986012@out_context-00000000;1 setting read format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Channel PJSIP/0986011-00000000 setting write format path: alaw -> alaw [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Topology of PJSIP/0986011-00000000 already matches what is requested so ignoring topology change request [Feb 28 10:39:45] DEBUG[23008][C-00000001] channel.c: Topology of PJSIP/0986011-00000000 already matches what is requested so ignoring topology change request [Feb 28 10:39:45] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (402 bytes) from UDP:10.199.251.2:5060 ---> ACK sip:10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK3518007277 From: "0986011" ;tag=4127690886 To: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c Call-ID: 1_2384255746@10.199.251.2 CSeq: 2 ACK Contact: Max-Forwards: 70 User-Agent: Yealink SIP-T42G 29.83.0.35 Content-Length: 0 [Feb 28 10:39:45] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c400cbc8 for Request msg ACK/cseq=2 (rdata0x7fa06c0008e8) [Feb 28 10:39:45] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000025 associated with dialog dlg0x7fa0c400cbc8 [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current transaction state is Terminated [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The transaction state change event is USER [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current inv state is CONNECTING [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Received request [Feb 28 10:39:45] DEBUG[22893] res_pjsip_session.c: Method is ACK [Feb 28 10:39:45] DEBUG[23013][C-00000001] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 10.199.48.8:5063 [Feb 28 10:39:45] VERBOSE[23013][C-00000001] res_rtp_asterisk.c: 0x7fa0c403a790 -- Strict RTP switching to RTP target address 10.199.48.8:5062 as source [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge.c: Move-swap optimizing Local/0986012@out_context-00000000;1 <-- PJSIP/0986012-00000002. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Moving 0x7fa1400105c0(PJSIP/0986012-00000002) into bridge 1c30d81b-9854-4b46-961b-e51695dfd91f swapping with Local/0986012@out_context-00000000;1 [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: pulling 0x7fa1400105c0(PJSIP/0986012-00000002) [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_channel.c: Channel PJSIP/0986012-00000002 left 'simple_bridge' basic-bridge [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa1400105c0(PJSIP/0986012-00000002) is leaving simple_bridge technology [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Channel PJSIP/0986012-00000002 will survive this bridge; clearing outgoing (dialed) flag [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pushing 0x7fa1400105c0(PJSIP/0986012-00000002) by swapping with 0x7fa13c017e50(Local/0986012@out_context-00000000;1) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Setting 0x7fa13c017e50(Local/0986012@out_context-00000000;1) state from:0 to:2 [Feb 28 10:39:45] DEBUG[22888] cdr.c: Finalized CDR for Local/0986012@out_context-00000000;2 - start 1551339583.145873 answer 1551339585.075785 end 1551339585.091973 dispo ANSWERED [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pulling 0x7fa13c017e50(Local/0986012@out_context-00000000;1) [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_channel.c: Channel Local/0986012@out_context-00000000;1 left 'simple_bridge' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c017e50(Local/0986012@out_context-00000000;1) is leaving simple_bridge technology [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_channel.c: Channel PJSIP/0986012-00000002 swapped with Local/0986012@out_context-00000000;1 into 'simple_bridge' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Checking compatability for channels 'PJSIP/0986011-00000000' and 'PJSIP/0986012-00000002' [Feb 28 10:39:45] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986011-00000000 - start 1551339583.146405 answer 1551339585.075843 end 1551339585.092050 dispo ANSWERED [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Chose bridge technology native_rtp [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: switching from simple_bridge technology to native_rtp [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling native_rtp technology constructor [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: moving 0x7fa13c015470(PJSIP/0986011-00000000) to dummy bridge temporarily [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c015470(PJSIP/0986011-00000000) is leaving simple_bridge technology (dummy) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling simple_bridge technology stop [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa1400105c0(PJSIP/0986012-00000002) is joining native_rtp technology [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Channel 'PJSIP/0986012-00000002' is joining bridge tech [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Attaching hook data 0x7fa140012f20 to 'PJSIP/0986012-00000002' [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c015470(PJSIP/0986011-00000000) is joining native_rtp technology [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Channel 'PJSIP/0986011-00000000' is joining bridge tech [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Attaching hook data 0x7fa140011a20 to 'PJSIP/0986011-00000000' [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Tech starting 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' with target 'none' [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' in stack [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling native_rtp technology start [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling simple_bridge technology destructor [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_native_rtp.c: Bridge 'ac48b971-a755-4b2e-9417-0739bce5ba0e' can not use native RTP bridge as two channels are required [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Chose bridge technology simple_bridge [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e is already using the new technology. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Setting 0x7fa140010910(Local/0986012@out_context-00000000;2) state from:0 to:2 [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: pulling 0x7fa140010910(Local/0986012@out_context-00000000;2) [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Checking compatability for channels 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' [Feb 28 10:39:45] VERBOSE[23010][C-00000001] bridge_channel.c: Channel Local/0986012@out_context-00000000;2 left 'simple_bridge' basic-bridge [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge_channel.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: 0x7fa140010910(Local/0986012@out_context-00000000;2) is leaving simple_bridge technology [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: dissolving bridge with cause 16(Normal Clearing) [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: queueing action type:13 sub:1001 [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Chose bridge technology native_rtp [Feb 28 10:39:45] DEBUG[23013][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is already using the new technology. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e is dissolved, not performing smart bridge operation. [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: actually destroying basic bridge, nobody wants it anymore [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: calling basic bridge destructor [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: calling simple_bridge technology stop [Feb 28 10:39:45] DEBUG[23010][C-00000001] bridge.c: Bridge ac48b971-a755-4b2e-9417-0739bce5ba0e: calling simple_bridge technology destructor [Feb 28 10:39:45] DEBUG[23010][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Checking compatability for channels 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Chose bridge technology native_rtp [Feb 28 10:39:45] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is already using the new technology. [Feb 28 10:39:45] DEBUG[23014][C-00000001] channel.c: Channel 0x7fa13c012520 'Local/0986012@out_context-00000000;1' hanging up. Refs: 2 [Feb 28 10:39:45] DEBUG[23014][C-00000001] channel.c: Channel 0x7fa13c012520 'Local/0986012@out_context-00000000;1' destroying [Feb 28 10:39:45] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986012-00000002 - start 1551339585.092064 answer 1551339585.092064 end 1551339585.092538 dispo ANSWERED [Feb 28 10:39:45] DEBUG[22888] cdr.c: CDR for Local/0986012@out_context-00000000;1 is dialed and has no Party B; discarding [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for Local - 0986012@out_context [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for Local/0986012@out_context - state 1 (Not in use) [Feb 28 10:39:45] DEBUG[22916] app_queue.c: Device 'Local/0986012@out_context' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:45] DEBUG[23010][C-00000001] pbx.c: Spawn extension (out_context,0986012,1) exited non-zero on 'Local/0986012@out_context-00000000;2' [Feb 28 10:39:45] VERBOSE[23010][C-00000001] pbx.c: Spawn extension (out_context, 0986012, 1) exited non-zero on 'Local/0986012@out_context-00000000;2' [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'Local/0986012@out_context-00000000;2' [Feb 28 10:39:45] DEBUG[23010][C-00000001] pbx_lua.c: Looking up h@out_context:1 [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel 0x7fa13c015b10 'Local/0986012@out_context-00000000;2' hanging up. Refs: 2 [Feb 28 10:39:45] DEBUG[23010][C-00000001] channel.c: Channel 0x7fa13c015b10 'Local/0986012@out_context-00000000;2' destroying [Feb 28 10:39:45] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for Local - 0986012@out_context [Feb 28 10:39:45] DEBUG[22880] core_local.c: Checking if extension 0986012@out_context exists (devicestate) [Feb 28 10:39:45] DEBUG[22880] pbx_lua.c: Looking up 0986012@out_context:1 [Feb 28 10:39:45] DEBUG[22880] devicestate.c: Changing state for Local/0986012@out_context - state 1 (Not in use) [Feb 28 10:39:45] DEBUG[22916] app_queue.c: Device 'Local/0986012@out_context' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR 'CUCM8_Sub2' [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying contact 'CUCM8_Sub2@@418ed9253a4092108de370f8f2fa39d9' on AOR 'CUCM8_Sub2' [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: Wrapper created [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: Set timer to 3000 msec [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.77.1.109' [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.77.1.109' is 'UDP' [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.77.1.109' is an IP address, skipping resolution [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:39:46] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (423 bytes) to UDP:10.77.1.109:5060 ---> OPTIONS sip:10.77.1.109:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj8e921936-28d9-454c-a772-ead73cb0b0b3 From: ;tag=a03e3979-c089-44ca-99c0-f90a7880e12f To: Contact: Call-ID: b4e60248-1317-46f2-bfb4-7aa594ff9897 CSeq: 51163 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:46] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (443 bytes) from UDP:10.77.1.109:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj8e921936-28d9-454c-a772-ead73cb0b0b3 From: ;tag=a03e3979-c089-44ca-99c0-f90a7880e12f To: ;tag=519989648 Date: Thu, 28 Feb 2019 07:39:46 GMT Call-ID: b4e60248-1317-46f2-bfb4-7aa594ff9897 CSeq: 51163 OPTIONS Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 [Feb 28 10:39:46] DEBUG[22892] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=51163 (rdata0x7fa06c0008e8). Using request transaction as basis. [Feb 28 10:39:46] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa0c40267b8 for Response msg 200/OPTIONS/cseq=51163 (rdata0x7fa06c0008e8). [Feb 28 10:39:46] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/CUCM8_Sub2-00000041 on transaction tsx0x7fa0c40267b8 [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: PJSIP tsx response received [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: Cancelling timer [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: Timer cancelled [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: Callbacks executed [Feb 28 10:39:46] DEBUG[22893] res_pjsip.c: 0x7fa0c40422a0: wrapper destroyed [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_options.c: Endpoint state compositor 'CUCM8_Sub2' is online as AOR 'CUCM8_Sub2' is available [Feb 28 10:39:46] VERBOSE[22893] res_pjsip/pjsip_configuration.c: Endpoint CUCM8_Sub2 is now Reachable [Feb 28 10:39:46] VERBOSE[22893] res_pjsip/pjsip_options.c: Contact CUCM8_Sub2/sip:10.77.1.109:5060 is now Reachable. RTT: 1.149 msec [Feb 28 10:39:46] DEBUG[22893] res_pjsip/pjsip_options.c: AOR 'CUCM8_Sub2' now has 1 available contacts [Feb 28 10:39:46] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - CUCM8_Sub2 [Feb 28 10:39:46] DEBUG[22880] devicestate.c: Changing state for PJSIP/CUCM8_Sub2 - state 1 (Not in use) [Feb 28 10:39:46] DEBUG[22916] app_queue.c: Device 'PJSIP/CUCM8_Sub2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:49] DEBUG[23013][C-00000001] res_rtp_asterisk.c: Got RTCP report of 60 bytes from 10.199.48.8:5063 [Feb 28 10:39:50] VERBOSE[23013][C-00000001] res_rtp_asterisk.c: 0x7fa0c403a790 -- Strict RTP learning complete - Locking on source address 10.199.48.8:5062 [Feb 28 10:39:52] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (501 bytes) from UDP:10.199.48.8:5060 ---> BYE sip:asterisk@10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.48.8:5060;branch=z9hG4bK0014c0b39939e91198b231367a0894f6;rport From: ;tag=0033caad9939e91198b231367a0894f6 To: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 CSeq: 782 BYE Contact: Max-Forwards: 70 User-Agent: SIPPER for PhonerLite Content-Length: 0 [Feb 28 10:39:52] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c40110a8 for Request msg BYE/cseq=782 (rdata0x7fa06c0008e8) [Feb 28 10:39:52] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/0986012-0000005f associated with dialog dlg0x7fa0c40110a8 [Feb 28 10:39:52] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (394 bytes) to UDP:10.199.48.8:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.199.48.8:5060;rport=5060;received=10.199.48.8;branch=z9hG4bK0014c0b39939e91198b231367a0894f6 Call-ID: 9966623c-823b-4b3b-96fb-ab430d191f31 From: ;tag=0033caad9939e91198b231367a0894f6 To: "Test" ;tag=06bce51c-838b-4d65-ba13-8c22109ac2f0 CSeq: 782 BYE Server: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current transaction state is Completed [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Received request [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Method is BYE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986012(PJSIP/0986012-00000002)' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fa0c40267b8 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current transaction state is Completed [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_channel.c: Setting 0x7fa1400105c0(PJSIP/0986012-00000002) state from:0 to:1 [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pulling 0x7fa1400105c0(PJSIP/0986012-00000002) [Feb 28 10:39:52] VERBOSE[23013][C-00000001] bridge_channel.c: Channel PJSIP/0986012-00000002 left 'native_rtp' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa1400105c0(PJSIP/0986012-00000002) is leaving native_rtp technology [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Channel 'PJSIP/0986012-00000002' is leaving bridge tech [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Detaching hook data 0x7fa140013428 from 'PJSIP/0986012-00000002' [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Tech stopping 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' with target 'none' [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/0986012-00000002' and 'PJSIP/0986011-00000000' - media will flow through Asterisk core [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7fa140012f20 [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: dissolving bridge with cause 16(Normal Clearing) [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge_channel.c: Setting 0x7fa13c015470(PJSIP/0986011-00000000) state from:0 to:2 [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: queueing action type:13 sub:1001 [Feb 28 10:39:52] DEBUG[23013][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is dissolved, not performing smart bridge operation. [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: pulling 0x7fa13c015470(PJSIP/0986011-00000000) [Feb 28 10:39:52] VERBOSE[23008][C-00000001] bridge_channel.c: Channel PJSIP/0986011-00000000 left 'native_rtp' basic-bridge <1c30d81b-9854-4b46-961b-e51695dfd91f> [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge_channel.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: 0x7fa13c015470(PJSIP/0986011-00000000) is leaving native_rtp technology [Feb 28 10:39:52] DEBUG[23013][C-00000001] channel.c: Channel 0x7fa14000c7c0 'PJSIP/0986012-00000002' hanging up. Refs: 2 [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Channel 'PJSIP/0986011-00000000' is leaving bridge tech [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge_native_rtp.c: Bridge '1c30d81b-9854-4b46-961b-e51695dfd91f'. Detaching hook data 0x7fa14000d9a8 from 'PJSIP/0986011-00000000' [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7fa140011a20 [Feb 28 10:39:52] DEBUG[23013][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f is dissolved, not performing smart bridge operation. [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: actually destroying basic bridge, nobody wants it anymore [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling basic bridge destructor [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling native_rtp technology stop [Feb 28 10:39:52] DEBUG[23008][C-00000001] bridge.c: Bridge 1c30d81b-9854-4b46-961b-e51695dfd91f: calling native_rtp technology destructor [Feb 28 10:39:52] DEBUG[22888] cdr.c: Finalized CDR for PJSIP/0986011-00000000 - start 1551339585.092073 answer 1551339585.092073 end 1551339592.880220 dispo ANSWERED [Feb 28 10:39:52] DEBUG[22893] rtp_engine.c: Destroyed RTP instance '0x7fa0c40325a0' [Feb 28 10:39:52] DEBUG[22893] channel.c: Channel 0x7fa14000c7c0 'PJSIP/0986012-00000002' destroying [Feb 28 10:39:52] DEBUG[23008][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 28 10:39:52] DEBUG[22888] cdr.c: CDR for PJSIP/0986012-00000002 is dialed and has no Party B; discarding [Feb 28 10:39:52] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986012 [Feb 28 10:39:52] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986012 - state 1 (Not in use) [Feb 28 10:39:52] DEBUG[22916] app_queue.c: Device 'PJSIP/0986012' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:52] DEBUG[23008][C-00000001] pbx.c: Spawn extension (out_context,0986010,1) exited non-zero on 'PJSIP/0986011-00000000' [Feb 28 10:39:52] VERBOSE[23008][C-00000001] pbx.c: Spawn extension (out_context, 0986010, 1) exited non-zero on 'PJSIP/0986011-00000000' [Feb 28 10:39:52] DEBUG[23008][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/0986011-00000000' [Feb 28 10:39:52] DEBUG[23008][C-00000001] pbx_lua.c: Looking up h@out_context:1 [Feb 28 10:39:52] DEBUG[23008][C-00000001] channel.c: Channel 0x7fa0c402b1b0 'PJSIP/0986011-00000000' hanging up. Refs: 2 [Feb 28 10:39:52] DEBUG[23008][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Feb 28 10:39:52] DEBUG[22893] rtp_engine.c: Destroyed RTP instance '0x7fa0c4026390' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Method is BYE [Feb 28 10:39:52] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.199.251.2' [Feb 28 10:39:52] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.199.251.2' is 'UDP' [Feb 28 10:39:52] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.199.251.2' is an IP address, skipping resolution [Feb 28 10:39:52] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP request (422 bytes) to UDP:10.199.251.2:5060 ---> BYE sip:0986011@10.199.251.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.200.32.222:5060;rport;branch=z9hG4bKPj0e672a33-aac8-48e4-9505-897c9596fc66 From: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c To: "0986011" ;tag=4127690886 Call-ID: 1_2384255746@10.199.251.2 CSeq: 5371 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011(PJSIP/0986011-00000000)' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fa0c4042cd8 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current transaction state is Calling [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The transaction state change event is TX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is CONFIRMED [Feb 28 10:39:52] DEBUG[22893] channel.c: Channel 0x7fa0c402b1b0 'PJSIP/0986011-00000000' destroying [Feb 28 10:39:52] DEBUG[22880] devicestate.c: No provider found, checking channel drivers for PJSIP - 0986011 [Feb 28 10:39:52] DEBUG[22880] devicestate.c: Changing state for PJSIP/0986011 - state 1 (Not in use) [Feb 28 10:39:52] DEBUG[22916] app_queue.c: Device 'PJSIP/0986011' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 10:39:52] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP response (365 bytes) from UDP:10.199.251.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.200.32.222:5060;rport=5060;branch=z9hG4bKPj0e672a33-aac8-48e4-9505-897c9596fc66 From: ;tag=89e5a007-a5f0-472b-a527-ba5118dd864c To: "0986011" ;tag=4127690886 Call-ID: 1_2384255746@10.199.251.2 CSeq: 5371 BYE User-Agent: Yealink SIP-T42G 29.83.0.35 Content-Length: 0 [Feb 28 10:39:52] DEBUG[22892] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fa0c400cbc8 for Response msg 200/BYE/cseq=5371 (rdata0x7fa06c0008e8) [Feb 28 10:39:52] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000025 associated with dialog dlg0x7fa0c400cbc8 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011()' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: There is no transaction involved in this state change [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Source of transaction state change is RX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Response is 200 OK [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The state change pertains to the endpoint '0986011()' [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fa0c4042cd8 [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current transaction state is Completed [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The transaction state change event is RX_MSG [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Received response [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: Response is 200 OK [Feb 28 10:39:52] DEBUG[22893] res_pjsip_session.c: BYE received final response code 200 [Feb 28 10:39:53] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (847 bytes) from UDP:10.199.251.2:5060 ---> REGISTER sip:10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK3019741514 From: "0986011" ;tag=1891890762 To: "0986011" Call-ID: 1_564819577@10.199.251.2 CSeq: 3 REGISTER Contact: Authorization: Digest username="0986011", realm="asterisk", nonce="1551336593/6fa2fe54f19083edbc6f427fcabcc5af", uri="sip:10.200.32.222:5060", response="b19c4507fa4295a28b3a876794d21e84", algorithm=MD5, cnonce="0a4f113b", opaque="7ce11731763f407b", qop=auth, nc=00000002 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T42G 29.83.0.35 Expires: 3600 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Feb 28 10:39:53] DEBUG[22892] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=3 (rdata0x7fa06c0008e8) [Feb 28 10:39:53] DEBUG[22892] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000036 to use for Request msg REGISTER/cseq=3 (rdata0x7fa06c0008e8) [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Pub' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub1' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub2' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Identified by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0986011'. [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:53] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (506 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK3019741514 Call-ID: 1_564819577@10.199.251.2 From: "0986011" ;tag=1891890762 To: "0986011" ;tag=z9hG4bK3019741514 CSeq: 3 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1551339593/f9e003f1e06d9433eee4b580ccf79de9",opaque="653788d8587b0111",stale=true,algorithm=md5,qop="auth" Server: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:53] VERBOSE[22892] res_pjsip_logger.c: <--- Received SIP request (847 bytes) from UDP:10.199.251.2:5060 ---> REGISTER sip:10.200.32.222:5060 SIP/2.0 Via: SIP/2.0/UDP 10.199.251.2:5060;branch=z9hG4bK1534871608 From: "0986011" ;tag=1891890762 To: "0986011" Call-ID: 1_564819577@10.199.251.2 CSeq: 4 REGISTER Contact: Authorization: Digest username="0986011", realm="asterisk", nonce="1551339593/f9e003f1e06d9433eee4b580ccf79de9", uri="sip:10.200.32.222:5060", response="01397dcbc7f2d7efb422610e64931182", algorithm=MD5, cnonce="0a4f113b", opaque="653788d8587b0111", qop=auth, nc=00000001 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T42G 29.83.0.35 Expires: 3600 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Feb 28 10:39:53] DEBUG[22892] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=4 (rdata0x7fa06c0008e8) [Feb 28 10:39:53] DEBUG[22892] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000036 to use for Request msg REGISTER/cseq=4 (rdata0x7fa06c0008e8) [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Pub' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub1' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_ip.c: Source address 10.199.251.2:5060 does not match identify 'CUCM8_Sub2' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_endpoint_identifier_user.c: Identified by From username '0986011' domain '10.200.32.222' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0986011'. [Feb 28 10:39:53] DEBUG[22893] res_pjsip_authenticator_digest.c: Calculated nonce 1551339593/f9e003f1e06d9433eee4b580ccf79de9. Actual nonce is 1551339593/f9e003f1e06d9433eee4b580ccf79de9 [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.200.32.222' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.200.32.222' and port ''. [Feb 28 10:39:53] DEBUG[22893] netsock2.c: Splitting '10.199.251.2' into... [Feb 28 10:39:53] DEBUG[22893] netsock2.c: ...host '10.199.251.2' and port ''. [Feb 28 10:39:53] DEBUG[22893] res_pjsip_registrar.c: Matched id '0986011' to aor '0986011' [Feb 28 10:39:53] DEBUG[22893] res_pjsip_registrar.c: Matched aor '0986011' by To username [Feb 28 10:39:53] DEBUG[22893] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0) [Feb 28 10:39:53] DEBUG[22893] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Feb 28 10:39:53] DEBUG[22893] res_pjsip_registrar.c: Refreshed contact 'sip:0986011@10.199.251.2:5060' on AOR '0986011' with new expiration of 3600 seconds [Feb 28 10:39:53] VERBOSE[22893] res_pjsip_logger.c: <--- Transmitting SIP response (446 bytes) to UDP:10.199.251.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.199.251.2:5060;rport=5060;received=10.199.251.2;branch=z9hG4bK1534871608 Call-ID: 1_564819577@10.199.251.2 From: "0986011" ;tag=1891890762 To: "0986011" ;tag=z9hG4bK1534871608 CSeq: 4 REGISTER Date: Thu, 28 Feb 2019 07:39:53 GMT Contact: ;expires=3599 Expires: 3600 Server: Asterisk PBX 16.2.0 Content-Length: 0 [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The state change pertains to the endpoint '0986011()' [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7fa0c4042cd8 [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The current transaction state is Terminated [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The transaction state change event is TIMER [Feb 28 10:39:57] DEBUG[22892] res_pjsip_session.c: The current inv state is DISCONNCTD [Feb 28 10:39:57] DEBUG[22893] res_pjsip_session.c: Destroying SIP session with endpoint 0986011 [Feb 28 10:40:02] DEBUG[22895] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:40:02] DEBUG[22897] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:40:02] DEBUG[22890] threadpool.c: Destroying worker thread 7 [Feb 28 10:40:02] DEBUG[22890] threadpool.c: Destroying worker thread 9 [Feb 28 10:40:02] DEBUG[22896] threadpool.c: Worker thread idle timeout reached. Dying. [Feb 28 10:40:02] DEBUG[22890] threadpool.c: Destroying worker thread 8 [Feb 28 10:40:02] DEBUG[22902] res_pjsip_registrar.c: Woke up at 1551339602 Interval: 30 [Feb 28 10:40:02] DEBUG[22902] res_pjsip_registrar.c: Expiring 0 contacts [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR 'CUCM8_Pub' [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_options.c: Qualifying contact 'CUCM8_Pub@@af5e5958d3470a040f13c57d7600ffcf' on AOR 'CUCM8_Pub' [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: Wrapper created [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: Set timer to 3000 msec [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.77.1.107' [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_resolver.c: Transport type for target '10.77.1.107' is 'UDP' [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_resolver.c: Target '10.77.1.107' is an IP address, skipping resolution [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.200.32.222:5060 (this may be re-written again later) [Feb 28 10:40:02] DEBUG[22892] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=54029 (rdata0x7fa06c0008e8). Using request transaction as basis. [Feb 28 10:40:02] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found transaction tsx0x7fa0c400cbc8 for Response msg 200/OPTIONS/cseq=54029 (rdata0x7fa06c0008e8). [Feb 28 10:40:02] DEBUG[22892] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/CUCM8_Pub-0000003e on transaction tsx0x7fa0c400cbc8 [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: PJSIP tsx response received [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: Cancelling timer [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: Timer cancelled [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: Callbacks executed [Feb 28 10:40:02] DEBUG[22893] res_pjsip.c: 0x7fa0c4008d30: wrapper destroyed [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_options.c: Contact CUCM8_Pub/sip:10.77.1.107:5060 status didn't change: Reachable, RTT: 1.103 msec [Feb 28 10:40:02] DEBUG[22893] res_pjsip/pjsip_options.c: AOR 'CUCM8_Pub' now has 1 available contacts