[Apr 19 20:52:01] Asterisk 14.4.0 built by root @ switch1 on a x86_64 running Linux on 2017-04-19 21:50:57 UTC [Apr 19 20:52:24] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (3576 bytes) from TLS:192.168.105.105:36799 ---> INVITE sip:102@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK3bdf6b30954AA825 From: "103" ;tag=33B7F006-6C84C87B To: CSeq: 1 INVITE Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Supported: replaces,100rel Allow-Events: conference,talk,hold Max-Forwards: 70 Content-Type: application/sdp Content-Length: 2845 v=0 o=- 1492653144 1492653144 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10941 RTP/SAVP 9 0 8 18 127 a=crypto:193 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 a=crypto:194 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP a=crypto:195 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTP a=crypto:196 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP a=crypto:197 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTCP a=crypto:198 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTCP a=crypto:199 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTP UNENCRYPTED_SRTCP a=crypto:200 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP UNENCRYPTED_SRTCP 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=rtpmap:127 telephone-event/8000 a=ice-pwd:q/OJqu48kn/Fx3CC7q23xtDW/Eyeball a=ice-ufrag:AFN7G6 a=rtcp:10942 a=candidate:1 1 UDP 2130706431 192.168.105.105 2284 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2285 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 34718 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 57797 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 34718 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 57797 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10941 typ srflx raddr 192.168.105.105 rport 2484 a=candidate:4 2 UDP 1694498814 24.214.53.147 10942 typ srflx raddr 192.168.105.105 rport 2485 m=audio 10941 RTP/AVP 9 0 8 18 127 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=rtpmap:127 telephone-event/8000 a=ice-pwd:q/OJqu48kn/Fx3CC7q23xtDW/Eyeball a=ice-ufrag:AFN7G6 a=rtcp:10942 a=candidate:1 1 UDP 2130706431 192.168.105.105 2284 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2285 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 34718 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 57797 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 34718 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 57797 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10941 typ srflx raddr 192.168.105.105 rport 2484 a=candidate:4 2 UDP 1694498814 24.214.53.147 10942 typ srflx raddr 192.168.105.105 rport 2485 [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg INVITE/cseq=1 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '103'. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (568 bytes) to TLS:192.168.105.105:36799 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.105:36799;rport=36799;received=192.168.105.105;branch=z9hG4bK3bdf6b30954AA825 Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 From: "103" ;tag=33B7F006-6C84C87B To: ;tag=z9hG4bK3bdf6b30954AA825 CSeq: 1 INVITE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653144/7e08d5ff27a1e9d7fca4ebe3f2f279d0",opaque="6ebd9e453b3efd1e",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:24] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (650 bytes) from TLS:192.168.105.105:36799 ---> ACK sip:102@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK3bdf6b30954AA825 From: "103" ;tag=33B7F006-6C84C87B To: ;tag=z9hG4bK3bdf6b30954AA825 CSeq: 1 ACK Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Max-Forwards: 70 Content-Length: 0 [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg ACK/cseq=1 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (3913 bytes) from TLS:192.168.105.105:36799 ---> INVITE sip:102@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK7061e279515652AE From: "103" ;tag=33B7F006-6C84C87B To: CSeq: 2 INVITE Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Supported: replaces,100rel Allow-Events: conference,talk,hold Authorization: Digest username="103", realm="switch1.isc.corp.gtinow.com", nonce="1492653144/7e08d5ff27a1e9d7fca4ebe3f2f279d0", qop=auth, cnonce="M6t8HaKecRkP/mV", nc=00000001, opaque="6ebd9e453b3efd1e", uri="sip:102@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls", response="d6a46987ade19bb072ea7bbf9ace4ad4", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 2845 v=0 o=- 1492653144 1492653144 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10941 RTP/SAVP 9 0 8 18 127 a=crypto:193 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 a=crypto:194 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP a=crypto:195 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTP a=crypto:196 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP a=crypto:197 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTCP a=crypto:198 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTCP a=crypto:199 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNENCRYPTED_SRTP UNENCRYPTED_SRTCP a=crypto:200 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP UNENCRYPTED_SRTCP 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=rtpmap:127 telephone-event/8000 a=ice-pwd:q/OJqu48kn/Fx3CC7q23xtDW/Eyeball a=ice-ufrag:AFN7G6 a=rtcp:10942 a=candidate:1 1 UDP 2130706431 192.168.105.105 2284 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2285 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 34718 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 57797 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 34718 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 57797 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10941 typ srflx raddr 192.168.105.105 rport 2484 a=candidate:4 2 UDP 1694498814 24.214.53.147 10942 typ srflx raddr 192.168.105.105 rport 2485 m=audio 10941 RTP/AVP 9 0 8 18 127 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=rtpmap:127 telephone-event/8000 a=ice-pwd:q/OJqu48kn/Fx3CC7q23xtDW/Eyeball a=ice-ufrag:AFN7G6 a=rtcp:10942 a=candidate:1 1 UDP 2130706431 192.168.105.105 2284 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2285 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 34718 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 57797 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 34718 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 57797 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10941 typ srflx raddr 192.168.105.105 rport 2484 a=candidate:4 2 UDP 1694498814 24.214.53.147 10942 typ srflx raddr 192.168.105.105 rport 2485 [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg INVITE/cseq=2 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '103'. [Apr 19 20:52:24] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653144/7e08d5ff27a1e9d7fca4ebe3f2f279d0. Actual nonce is 1492653144/7e08d5ff27a1e9d7fca4ebe3f2f279d0 [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:24] DEBUG[4747] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg INVITE/cseq=2 (rdata0x2700588) [Apr 19 20:52:24] VERBOSE[4747] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '0.0.0.0' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 19 20:52:24] DEBUG[4747] res_pjsip_sdp_rtp.c: Transport transport-tls-ipv4 bound to 0.0.0.0: Using it for RTP media. [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f67fc022b38' [Apr 19 20:52:24] DEBUG[4747] res_rtp_asterisk.c: Allocated port 12966 for RTP instance '0x7f67fc022b38' [Apr 19 20:52:24] DEBUG[4747] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:12966 (12966) for RTP instance '0x7f67fc022b38' [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: RTP instance '0x7f67fc022b38' is setup and ready to go [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting 'switch1' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host 'switch1' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:24] DEBUG[4747] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f67fc022b38' [Apr 19 20:52:24] DEBUG[4747] res_srtp.c: local_key64 dc/LJt/GN3fET3cs20ySOSaQPrw+gRIavdPUPpwu len 40 [Apr 19 20:52:24] DEBUG[4747] res_srtp.c: Crypto attribute '193 AES_CM_128_HMAC_SHA1_80 inline:t8cVlHuSSmbu9EIQVQqM7Vi8JMOKTVO26b2vLdlE|2^31' accepted with lifetime '2147483648.000000', MKI '-' [Apr 19 20:52:24] DEBUG[4747] res_srtp.c: Adding new policy for SSRC 1152454746 [Apr 19 20:52:24] DEBUG[4747] res_srtp.c: SRTP policy activated [Apr 19 20:52:24] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:193 AES_CM_128_HMAC_SHA1_80 inline:dc/LJt/GN3fET3cs20ySOSaQPrw+gRIavdPUPpwu [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Setting tx payload type 127 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f67fc0469d0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f67fc0472e0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7f67fc046980) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f67fc047380) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 127 (0x7f67fc047330) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 0 (0x7f67fc0469d0) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 8 (0x7f67fc0472e0) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 9 (0x7f67fc046980) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 18 (0x7f67fc047380) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 127 (0x7f67fc047330) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 0 (0x7f67fc0469d0) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 8 (0x7f67fc0472e0) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 9 (0x7f67fc046980) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 18 (0x7f67fc047380) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 127 (0x7f67fc047330) from 0x7f67d22af4d0 to 0x7f67fc022d00 [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Method is INVITE, Response is 488 Not Acceptable Here [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (422 bytes) to TLS:192.168.105.105:36799 ---> SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/TLS 192.168.105.105:36799;rport=36799;received=192.168.105.105;branch=z9hG4bK7061e279515652AE Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 From: "103" ;tag=33B7F006-6C84C87B To: ;tag=79fc6756-56ff-4a8d-b008-bd703bb1fa5f CSeq: 2 INVITE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:24] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (663 bytes) from TLS:192.168.105.105:36799 ---> ACK sip:102@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK7061e279515652AE From: "103" ;tag=33B7F006-6C84C87B To: ;tag=79fc6756-56ff-4a8d-b008-bd703bb1fa5f CSeq: 2 ACK Call-ID: b74d4f5a-507230cf-e4481c84@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Max-Forwards: 70 Content-Length: 0 [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:24] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:24] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f680c006088 for Request msg ACK/cseq=2 (rdata0x26e8590) [Apr 19 20:52:24] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003b on dialog dlg0x7f680c006088 [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The current transaction state is Confirmed [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Received request [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Method is ACK [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The transaction state change event is TIMER [Apr 19 20:52:24] DEBUG[4746] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:24] DEBUG[4747] res_pjsip_session.c: Destroying SIP session with endpoint 103 [Apr 19 20:52:24] DEBUG[4747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc022b38' [Apr 19 20:52:24] DEBUG[4747] rtp_engine.c: Destroyed RTP instance '0x7f67fc022b38' [Apr 19 20:52:31] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (3576 bytes) from TLS:192.168.105.105:36799 ---> INVITE sip:200@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK58b44321A1934556 From: "103" ;tag=88A2ED77-7DF66B2C To: CSeq: 1 INVITE Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Supported: replaces,100rel Allow-Events: conference,talk,hold Max-Forwards: 70 Content-Type: application/sdp Content-Length: 2845 v=0 o=- 1492653151 1492653151 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10879 RTP/SAVP 9 0 8 18 127 a=crypto:201 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 a=crypto:202 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP a=crypto:203 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTP a=crypto:204 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP a=crypto:205 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTCP a=crypto:206 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTCP a=crypto:207 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTP UNENCRYPTED_SRTCP a=crypto:208 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP UNENCRYPTED_SRTCP 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=rtpmap:127 telephone-event/8000 a=ice-pwd:YCP/EeBokTD6aIUC4YIAksdN/Eyeball a=ice-ufrag:AFZjne a=rtcp:10880 a=candidate:1 1 UDP 2130706431 192.168.105.105 2222 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2223 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36065 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 53440 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36065 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 53440 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10879 typ srflx raddr 192.168.105.105 rport 2422 a=candidate:4 2 UDP 1694498814 24.214.53.147 10880 typ srflx raddr 192.168.105.105 rport 2423 m=audio 10879 RTP/AVP 9 0 8 18 127 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=rtpmap:127 telephone-event/8000 a=ice-pwd:YCP/EeBokTD6aIUC4YIAksdN/Eyeball a=ice-ufrag:AFZjne a=rtcp:10880 a=candidate:1 1 UDP 2130706431 192.168.105.105 2222 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2223 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36065 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 53440 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36065 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 53440 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10879 typ srflx raddr 192.168.105.105 rport 2422 a=candidate:4 2 UDP 1694498814 24.214.53.147 10880 typ srflx raddr 192.168.105.105 rport 2423 [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=1 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '103'. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (568 bytes) to TLS:192.168.105.105:36799 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.105:36799;rport=36799;received=192.168.105.105;branch=z9hG4bK58b44321A1934556 Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 From: "103" ;tag=88A2ED77-7DF66B2C To: ;tag=z9hG4bK58b44321A1934556 CSeq: 1 INVITE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653150/9da62475b042df200c9331ca7d97dd56",opaque="0507800730602a71",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:31] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (650 bytes) from TLS:192.168.105.105:36799 ---> ACK sip:200@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK58b44321A1934556 From: "103" ;tag=88A2ED77-7DF66B2C To: ;tag=z9hG4bK58b44321A1934556 CSeq: 1 ACK Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Max-Forwards: 70 Content-Length: 0 [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg ACK/cseq=1 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (3913 bytes) from TLS:192.168.105.105:36799 ---> INVITE sip:200@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK4e2f34aa53F63A1F From: "103" ;tag=88A2ED77-7DF66B2C To: CSeq: 2 INVITE Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Supported: replaces,100rel Allow-Events: conference,talk,hold Authorization: Digest username="103", realm="switch1.isc.corp.gtinow.com", nonce="1492653150/9da62475b042df200c9331ca7d97dd56", qop=auth, cnonce="2Gx4iWswNTcqJAm", nc=00000001, opaque="0507800730602a71", uri="sip:200@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls", response="358b6056d53ef25ad964f2b8c969e8fb", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 2845 v=0 o=- 1492653151 1492653151 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10879 RTP/SAVP 9 0 8 18 127 a=crypto:201 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 a=crypto:202 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP a=crypto:203 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTP a=crypto:204 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP a=crypto:205 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTCP a=crypto:206 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTCP a=crypto:207 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNENCRYPTED_SRTP UNENCRYPTED_SRTCP a=crypto:208 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31 UNAUTHENTICATED_SRTP UNENCRYPTED_SRTP UNENCRYPTED_SRTCP 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=rtpmap:127 telephone-event/8000 a=ice-pwd:YCP/EeBokTD6aIUC4YIAksdN/Eyeball a=ice-ufrag:AFZjne a=rtcp:10880 a=candidate:1 1 UDP 2130706431 192.168.105.105 2222 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2223 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36065 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 53440 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36065 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 53440 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10879 typ srflx raddr 192.168.105.105 rport 2422 a=candidate:4 2 UDP 1694498814 24.214.53.147 10880 typ srflx raddr 192.168.105.105 rport 2423 m=audio 10879 RTP/AVP 9 0 8 18 127 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=rtpmap:127 telephone-event/8000 a=ice-pwd:YCP/EeBokTD6aIUC4YIAksdN/Eyeball a=ice-ufrag:AFZjne a=rtcp:10880 a=candidate:1 1 UDP 2130706431 192.168.105.105 2222 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2223 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36065 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 53440 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36065 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 53440 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10879 typ srflx raddr 192.168.105.105 rport 2422 a=candidate:4 2 UDP 1694498814 24.214.53.147 10880 typ srflx raddr 192.168.105.105 rport 2423 [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=2 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '103' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '103'. [Apr 19 20:52:31] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653150/9da62475b042df200c9331ca7d97dd56. Actual nonce is 1492653150/9da62475b042df200c9331ca7d97dd56 [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:31] DEBUG[4747] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=2 (rdata0x2700588) [Apr 19 20:52:31] VERBOSE[4747] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '0.0.0.0' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 19 20:52:31] DEBUG[4747] res_pjsip_sdp_rtp.c: Transport transport-tls-ipv4 bound to 0.0.0.0: Using it for RTP media. [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f67fc01dea8' [Apr 19 20:52:31] DEBUG[4747] res_rtp_asterisk.c: Allocated port 17734 for RTP instance '0x7f67fc01dea8' [Apr 19 20:52:31] DEBUG[4747] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:17734 (17734) for RTP instance '0x7f67fc01dea8' [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: RTP instance '0x7f67fc01dea8' is setup and ready to go [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting 'switch1' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host 'switch1' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:31] DEBUG[4747] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f67fc01dea8' [Apr 19 20:52:31] DEBUG[4747] res_srtp.c: local_key64 tPkhgRizmLySjrlMWLLBjEuSxrMk5Vxq+c30gx7l len 40 [Apr 19 20:52:31] DEBUG[4747] res_srtp.c: Crypto attribute '201 AES_CM_128_HMAC_SHA1_80 inline:S/EvDVXkAoShXlYqyzypU2ZoAhSvAcquLKbbSpIF|2^31' accepted with lifetime '2147483648.000000', MKI '-' [Apr 19 20:52:31] DEBUG[4747] res_srtp.c: Adding new policy for SSRC 1023766297 [Apr 19 20:52:31] DEBUG[4747] res_srtp.c: SRTP policy activated [Apr 19 20:52:31] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:201 AES_CM_128_HMAC_SHA1_80 inline:tPkhgRizmLySjrlMWLLBjEuSxrMk5Vxq+c30gx7l [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Setting tx payload type 127 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f67fc018850) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f67fc0188a0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7f67fc018800) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f67fc0473f0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 127 (0x7f67fc047550) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 0 (0x7f67fc018850) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 8 (0x7f67fc0188a0) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 9 (0x7f67fc018800) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 18 (0x7f67fc0473f0) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 127 (0x7f67fc047550) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 0 (0x7f67fc018850) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 8 (0x7f67fc0188a0) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 9 (0x7f67fc018800) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 18 (0x7f67fc0473f0) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 127 (0x7f67fc047550) from 0x7f67d22af4d0 to 0x7f67fc01e070 [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Method is INVITE, Response is 488 Not Acceptable Here [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (422 bytes) to TLS:192.168.105.105:36799 ---> SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/TLS 192.168.105.105:36799;rport=36799;received=192.168.105.105;branch=z9hG4bK4e2f34aa53F63A1F Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 From: "103" ;tag=88A2ED77-7DF66B2C To: ;tag=4bb340ad-3f44-4c2d-934c-6f3a39fb1f2c CSeq: 2 INVITE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:31] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (663 bytes) from TLS:192.168.105.105:36799 ---> ACK sip:200@switch1.isc.corp.gtinow.com:5061;user=phone;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK4e2f34aa53F63A1F From: "103" ;tag=88A2ED77-7DF66B2C To: ;tag=4bb340ad-3f44-4c2d-934c-6f3a39fb1f2c CSeq: 2 ACK Call-ID: 8d4e41cb-61a40880-1a576975@192.168.105.105 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Max-Forwards: 70 Content-Length: 0 [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:31] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:31] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f680c006088 for Request msg ACK/cseq=2 (rdata0x26e8590) [Apr 19 20:52:31] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000032 on dialog dlg0x7f680c006088 [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The current transaction state is Confirmed [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Received request [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Method is ACK [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The transaction state change event is TIMER [Apr 19 20:52:31] DEBUG[4746] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:31] DEBUG[4747] res_pjsip_session.c: Destroying SIP session with endpoint 103 [Apr 19 20:52:31] DEBUG[4747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01dea8' [Apr 19 20:52:31] DEBUG[4747] rtp_engine.c: Destroyed RTP instance '0x7f67fc01dea8' [Apr 19 20:52:37] DEBUG[4780] res_pjsip_registrar_expire.c: Woke up at 1492653157 Interval: 30 [Apr 19 20:52:37] DEBUG[4780] res_pjsip_registrar_expire.c: Expiring 0 contacts [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (1358 bytes) from TLS:192.168.105.30:56557 ---> INVITE sip:103@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---4168069da3fe6ce5;rport Max-Forwards: 70 Contact: To: From: "102";tag=ed7a174d Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 1 INVITE Content-Type: application/sdp User-Agent: Z 3.15.40006 rv2.8.20 Allow-Events: presence, kpml, talk Content-Length: 821 v=0 o=Z 0 0 IN IP4 192.168.105.30 s=Z c=IN IP4 192.168.105.30 t=0 0 m=audio 33198 RTP/SAVP 3 110 8 0 97 101 a=rtpmap:110 speex/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHplDIUg4cCoWQ== a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHplDIUg4cCoWQ== a=crypto:3 AES_192_CM_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHo= a=crypto:4 AES_192_CM_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHo= a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJ a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJ [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (552 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---4168069da3fe6ce5 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. From: "102" ;tag=ed7a174d To: ;tag=z9hG4bK-524287-1---4168069da3fe6ce5 CSeq: 1 INVITE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",opaque="27089af22bd6cc41",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (859 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---57bb062ecc048366;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=8b204d61 Call-ID: Zr_IumLnX2ocax0onyVEpg.. CSeq: 1 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence Allow-Events: presence, kpml, talk Content-Length: 279 open On the phone [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (559 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---57bb062ecc048366 Call-ID: Zr_IumLnX2ocax0onyVEpg.. From: "102" ;tag=8b204d61 To: "102" ;tag=z9hG4bK-524287-1---57bb062ecc048366 CSeq: 1 PUBLISH WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",opaque="79b651457180224b",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (589 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---5508fe5acbf709e7;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=265bf36d Call-ID: F1iyg96IuA1WL_IPmxcd3g.. CSeq: 1 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002f to use for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (398 bytes) from TLS:192.168.105.30:56557 ---> ACK sip:103@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---4168069da3fe6ce5;rport Max-Forwards: 70 To: ;tag=z9hG4bK-524287-1---4168069da3fe6ce5 From: "102";tag=ed7a174d Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 1 ACK Content-Length: 0 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg ACK/cseq=1 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (561 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---5508fe5acbf709e7 Call-ID: F1iyg96IuA1WL_IPmxcd3g.. From: "102" ;tag=265bf36d To: "102" ;tag=z9hG4bK-524287-1---5508fe5acbf709e7 CSeq: 1 SUBSCRIBE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",opaque="574770963bca1d00",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (1687 bytes) from TLS:192.168.105.30:56557 ---> INVITE sip:103@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---d52c0b0562d0b943;rport Max-Forwards: 70 Contact: To: From: "102";tag=ed7a174d Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 2 INVITE Content-Type: application/sdp User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",uri="sip:103@switch1.isc.corp.gtinow.com;transport=TLS",response="c74bee27ee20c0e8cba9f99e9a7fc6b3",cnonce="8672f99db949e4cd2c4dafc2eb49683a",nc=00000001,qop=auth,algorithm=md5,opaque="27089af22bd6cc41" Allow-Events: presence, kpml, talk Content-Length: 821 v=0 o=Z 0 0 IN IP4 192.168.105.30 s=Z c=IN IP4 192.168.105.30 t=0 0 m=audio 33198 RTP/SAVP 3 110 8 0 97 101 a=rtpmap:110 speex/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHplDIUg4cCoWQ== a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHplDIUg4cCoWQ== a=crypto:3 AES_192_CM_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHo= a=crypto:4 AES_192_CM_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJRkzx0TW/EHo= a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJ a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:9v4pACXvRQdLvSxXQK1NKNwl0Q7LQREvoipwSzuJ [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6. Actual nonce is 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000034 to use for Request msg INVITE/cseq=2 (rdata0x3d3f3e8) [Apr 19 20:52:38] VERBOSE[4747] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '0.0.0.0' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_pjsip_sdp_rtp.c: Transport transport-tls-ipv4 bound to 0.0.0.0: Using it for RTP media. [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Allocated port 11200 for RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:11200 (11200) for RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (1188 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---ee81774f2a8f8896;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=8b204d61 Call-ID: Zr_IumLnX2ocax0onyVEpg.. CSeq: 2 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="5118a7788a415d03bc06c8bc4a369cc0",cnonce="369d90c43a77df800996e251cc9192e2",nc=00000001,qop=auth,algorithm=md5,opaque="79b651457180224b" Event: presence Allow-Events: presence, kpml, talk Content-Length: 279 open On the phone [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4748] res_pjsip_authenticator_digest.c: Calculated nonce 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6. Actual nonce is 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6 [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4748] res_pjsip_pubsub.c: Event presence does not match asterisk-devicestate [Apr 19 20:52:38] DEBUG[4748] res_pjsip_pubsub.c: Event presence does not match asterisk-mwi [Apr 19 20:52:38] WARNING[4748] res_pjsip_pubsub.c: No registered publish handler for event presence [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4748] res_pjsip_logger.c: <--- Transmitting SIP response (390 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---ee81774f2a8f8896 Call-ID: Zr_IumLnX2ocax0onyVEpg.. From: "102" ;tag=8b204d61 To: "102" ;tag=z9hG4bK-524287-1---ee81774f2a8f8896 CSeq: 2 PUBLISH Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (918 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---12cafcf702995870;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=265bf36d Call-ID: F1iyg96IuA1WL_IPmxcd3g.. CSeq: 2 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="578ce8cf86bc5047b850a3b13ed7a313",cnonce="d2dd8edb19f86d23f8af2801eb662ff0",nc=00000001,qop=auth,algorithm=md5,opaque="574770963bca1d00" Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002f to use for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:38] DEBUG[4748] res_pjsip_authenticator_digest.c: Calculated nonce 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6. Actual nonce is 1492653158/506ce1cf729c26a7f8a744ef1ce3ffa6 [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] WARNING[4748] res_pjsip_pubsub.c: No registered subscribe handler for event presence.winfo [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4748] res_pjsip_logger.c: <--- Transmitting SIP response (392 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---12cafcf702995870 Call-ID: F1iyg96IuA1WL_IPmxcd3g.. From: "102" ;tag=265bf36d To: "102" ;tag=z9hG4bK-524287-1---12cafcf702995870 CSeq: 2 SUBSCRIBE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: RTP instance '0x7f67fc01c198' is setup and ready to go [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'switch1' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'switch1' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: local_key64 pbUcQn3/B7e9C+zYjEtcozw7cl/mRSPFTJIhbDg6 len 40 [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: local_key64 zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== len 64 [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Adding new policy for SSRC 1596017396 [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: SRTP policy activated [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x2379540) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 3 (0x2828ff0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x2379830) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 97 (0x7f67fc0435c0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x237d0e0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Crossover copying tx to rx payload mapping 110 (0x7f67fc0198a0) from 0x7f67d22af4d0 to 0x7f67d22af4d0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 0 (0x2379540) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 3 (0x2828ff0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 8 (0x2379830) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 97 (0x7f67fc0435c0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 101 (0x237d0e0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying rx payload mapping 110 (0x7f67fc0198a0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 0 (0x2379540) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 3 (0x2828ff0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 8 (0x2379830) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 97 (0x7f67fc0435c0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 101 (0x237d0e0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 110 (0x7f67fc0198a0) from 0x7f67d22af4d0 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== [Apr 19 20:52:38] DEBUG[4747] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (340 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 100 Trying Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---d52c0b0562d0b943 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. From: "102" ;tag=ed7a174d To: CSeq: 2 INVITE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102()' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is INCOMING [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102()' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is INCOMING [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Method is INVITE [Apr 19 20:52:38] DEBUG[4720] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 19 20:52:38] DEBUG[4747] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/102-00000000 [Apr 19 20:52:38] DEBUG[4807][C-00000001] pbx.c: Launching 'Dial' [Apr 19 20:52:38] VERBOSE[4807][C-00000001] pbx.c: Executing [103@demo:1] Dial("PJSIP/102-00000000", "PJSIP/103") in new stack [Apr 19 20:52:38] DEBUG[4747] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Apr 19 20:52:38] DEBUG[4747] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Apr 19 20:52:38] DEBUG[4747] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Apr 19 20:52:38] DEBUG[4747] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Apr 19 20:52:38] DEBUG[4747] config.c: extract uint from [36799] in [0, 4294967295] gives [36799](0) [Apr 19 20:52:38] VERBOSE[4807][C-00000001] app_dial.c: Called PJSIP/103 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '0.0.0.0' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_pjsip_sdp_rtp.c: Transport transport-tls-ipv4 bound to 0.0.0.0: Using it for RTP media. [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Allocated port 12734 for RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:12734 (12734) for RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/103-00000001 setting read format path: ulaw -> ulaw [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/103-00000001 setting write format path: ulaw -> ulaw [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: RTP instance '0x7f67fc01fb58' is setup and ready to go [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'switch1' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'switch1' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: local_key64 ljzFix6AVqX7AkQ/9F3yw3j5odq9bJHeI6nYUnzO len 40 [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ljzFix6AVqX7AkQ/9F3yw3j5odq9bJHeI6nYUnzO [Apr 19 20:52:38] DEBUG[4747] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Method is INVITE [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.105.105' [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.105.105' is 'TLS' [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Target '192.168.105.105' is an IP address, skipping resolution [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP request (1540 bytes) to TLS:192.168.105.105:36799 ---> INVITE sip:103@192.168.105.105:36799;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPje0c6ec8f-f71e-4f37-bc9a-6ce5dfbc5304;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: Contact: Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d CSeq: 12554 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX Content-Type: application/sdp Content-Length: 844 v=0 o=- 725991040 725991040 IN IP4 192.168.105.149 s=Asterisk c=IN IP4 192.168.105.149 t=0 0 m=audio 12734 RTP/SAVP 107 9 0 8 101 a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ljzFix6AVqX7AkQ/9F3yw3j5odq9bJHeI6nYUnzO a=ice-ufrag:5ec3fe0c4ae6332076dcb0c53c15403c a=ice-pwd:4cec772e64ace18706645f884bc7491e a=candidate:Hc0a86995 1 UDP 2130706431 192.168.105.149 12734 typ host a=candidate:S18d63593 1 UDP 1694498815 24.214.53.147 21395 typ srflx raddr 192.168.105.149 rport 12734 a=candidate:Hc0a86995 2 UDP 2130706430 192.168.105.149 12735 typ host a=candidate:S18d63593 2 UDP 1694498814 24.214.53.147 21396 typ srflx raddr 192.168.105.149 rport 12735 a=rtpmap:107 opus/48000/2 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is CALLING [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Calling [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is CALLING [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP response (493 bytes) from TLS:192.168.105.105:36799 ---> SIP/2.0 100 Trying Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPje0c6ec8f-f71e-4f37-bc9a-6ce5dfbc5304;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: "103" ;tag=D2B02F28-1995A21D CSeq: 12554 INVITE Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d Contact: User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Content-Length: 0 [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f67fc04d5a8 for Response msg 100/INVITE/cseq=12554 (rdata0x26e8590) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/103-0000005a on dialog dlg0x7f67fc04d5a8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is CALLING [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Response is 100 Trying [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP response (1544 bytes) from TLS:192.168.105.105:36799 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPje0c6ec8f-f71e-4f37-bc9a-6ce5dfbc5304;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: "103" ;tag=D2B02F28-1995A21D CSeq: 12554 INVITE Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d Contact: User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Content-Type: application/sdp Content-Length: 1007 v=0 o=- 1492653158 1492653158 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10881 RTP/SAVP 9 101 a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:lVyyPs7AHeTcQsyEQ4IYXgwisIQxID3ftC508g20 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv a=ice-pwd:E347brCukuFBKEtCjTl7RA2u/Eyeball a=ice-ufrag:AFxGcE a=rtcp:10882 a=candidate:1 1 UDP 2130706431 192.168.105.105 2224 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2225 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36006 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 60105 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36006 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 60105 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10881 typ srflx raddr 192.168.105.105 rport 2424 a=candidate:4 2 UDP 1694498814 24.214.53.147 10882 typ srflx raddr 192.168.105.105 rport 2425 [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f67fc04d5a8 for Response msg 183/INVITE/cseq=12554 (rdata0x26e8590) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/103-0000005a on dialog dlg0x7f67fc04d5a8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Response is 183 Session Progress [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Adding new policy for SSRC 2125486961 [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: SRTP policy activated [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:ljzFix6AVqX7AkQ/9F3yw3j5odq9bJHeI6nYUnzO [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] acl.c: For destination '24.214.53.147', our source address is '192.168.105.149'. [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f67d22aecf0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f67d22aecf0 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 9 (0x7f67fc078740) from 0x7f67d22aecf0 to 0x7f67fc01fd20 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 101 (0x237d0e0) from 0x7f67d22aecf0 to 0x7f67fc01fd20 [Apr 19 20:52:38] DEBUG[4747] channel.c: Channel PJSIP/103-00000001 setting read format path: g722 -> ulaw [Apr 19 20:52:38] DEBUG[4747] channel.c: Channel PJSIP/103-00000001 setting write format path: ulaw -> g722 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'passive' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'passive' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'passive' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'passive' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'active' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'active' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting 'active' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host 'active' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '24.214.53.147' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '24.214.53.147' and port ''. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Set role to CONTROLLING (0x7f67fc01fb58) [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Successfully created ICE checklist (0x7f67fc01fb58) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Response is 183 Session Progress [Apr 19 20:52:38] VERBOSE[4807][C-00000001] app_dial.c: PJSIP/103-00000001 is making progress passing it to PJSIP/102-00000000 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] res_srtp.c: SRTP remote key unchanged; maintaining current policy [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:38] DEBUG[4747] acl.c: For destination '192.168.105.30', our source address is '192.168.105.149'. [Apr 19 20:52:38] DEBUG[4747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01c198' [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f67d22aef30 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 0 (0x2379540) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 3 (0x2828ff0) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 8 (0x2379830) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 97 (0x7f67fc08e380) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 101 (0x237d0e0) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] rtp_engine.c: Copying tx payload mapping 110 (0x7f67fc08c470) from 0x7f67d22aef30 to 0x7f67fc01c360 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (1385 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---d52c0b0562d0b943 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. From: "102" ;tag=ed7a174d To: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 CSeq: 2 INVITE Server: Asterisk PBX Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Content-Type: application/sdp Content-Length: 798 v=0 o=- 0 2 IN IP4 192.168.105.149 s=Asterisk c=IN IP4 192.168.105.149 t=0 0 m=audio 11200 RTP/SAVP 0 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== a=ice-ufrag:045877512a7c6acc1df7aa333cecf2bf a=ice-pwd:4320c3fd7dbd89782da95acb766def79 a=candidate:Hc0a86995 1 UDP 2130706431 192.168.105.149 11200 typ host a=candidate:S18d63593 1 UDP 1694498815 24.214.53.147 19861 typ srflx raddr 192.168.105.149 rport 11200 a=candidate:Hc0a86995 2 UDP 2130706430 192.168.105.149 11201 typ host a=candidate:S18d63593 2 UDP 1694498814 24.214.53.147 19862 typ srflx raddr 192.168.105.149 rport 11201 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP response (530 bytes) from TLS:192.168.105.105:36799 ---> SIP/2.0 180 Ringing Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPje0c6ec8f-f71e-4f37-bc9a-6ce5dfbc5304;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: "103" ;tag=D2B02F28-1995A21D CSeq: 12554 INVITE Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d Contact: User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Allow-Events: conference,talk,hold Accept-Language: en Content-Length: 0 [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:38] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f67fc04d5a8 for Response msg 180/INVITE/cseq=12554 (rdata0x26e8590) [Apr 19 20:52:38] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/103-0000005a on dialog dlg0x7f67fc04d5a8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Response is 180 Ringing [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:38] DEBUG[4747] res_pjsip_session.c: Response is 180 Ringing [Apr 19 20:52:38] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 103 [Apr 19 20:52:38] DEBUG[4731] devicestate.c: Changing state for PJSIP/103 - state 6 (Ringing) [Apr 19 20:52:38] DEBUG[4794] app_queue.c: Device 'PJSIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 19 20:52:38] DEBUG[4738] app_queue.c: Extension '103@demo' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 19 20:52:38] VERBOSE[4807][C-00000001] app_dial.c: PJSIP/103-00000001 is ringing [Apr 19 20:52:38] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 102 [Apr 19 20:52:38] DEBUG[4731] devicestate.c: Changing state for PJSIP/102 - state 2 (In use) [Apr 19 20:52:38] DEBUG[4794] app_queue.c: Device 'PJSIP/102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 19 20:52:38] DEBUG[4738] app_queue.c: Extension '102@demo' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 19 20:52:38] DEBUG[4807][C-00000001] res_rtp_asterisk.c: 0x7f67fc0207a0 -- Probation learning mode pass with source address 192.168.105.30:33198 [Apr 19 20:52:38] VERBOSE[4807][C-00000001] res_rtp_asterisk.c: 0x7f67fc0207a0 -- Probation passed - setting RTP source address to 192.168.105.30:33198 [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Apr 19 20:52:38] DEBUG[4748] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4748] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:38] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:38] VERBOSE[4748] res_pjsip_logger.c: <--- Transmitting SIP response (1376 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 180 Ringing Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---d52c0b0562d0b943 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. From: "102" ;tag=ed7a174d To: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 CSeq: 2 INVITE Server: Asterisk PBX Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Contact: Content-Type: application/sdp Content-Length: 798 v=0 o=- 0 2 IN IP4 192.168.105.149 s=Asterisk c=IN IP4 192.168.105.149 t=0 0 m=audio 11200 RTP/SAVP 0 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== a=ice-ufrag:045877512a7c6acc1df7aa333cecf2bf a=ice-pwd:4320c3fd7dbd89782da95acb766def79 a=candidate:Hc0a86995 1 UDP 2130706431 192.168.105.149 11200 typ host a=candidate:S18d63593 1 UDP 1694498815 24.214.53.147 19861 typ srflx raddr 192.168.105.149 rport 11200 a=candidate:Hc0a86995 2 UDP 2130706430 192.168.105.149 11201 typ host a=candidate:S18d63593 2 UDP 1694498814 24.214.53.147 19862 typ srflx raddr 192.168.105.149 rport 11201 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The current transaction state is Proceeding [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:38] DEBUG[4748] res_pjsip_session.c: The current inv state is EARLY [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.105.105' [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.105.105' is 'TLS' [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_resolver.c: Target '192.168.105.105' is an IP address, skipping resolution [Apr 19 20:52:38] DEBUG[4747] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:38] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:46060' into... [Apr 19 20:52:38] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '46060'. [Apr 19 20:52:38] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP request (914 bytes) to TLS:192.168.105.105:46060 ---> NOTIFY sip:103@192.168.105.105:46060;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPj2d3b39e8-cae5-4600-b97d-8f47e1675fa4;alias From: ;tag=d73c730b-b0e4-4ca6-a5db-19542753d23f To: "103" ;tag=B2F5829D-8A4A7FD2 Contact: Call-ID: 3e9377a4-84922599-a54d7dce@192.168.105.105 CSeq: 25417 NOTIFY Event: dialog Subscription-State: active;expires=1486 Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: Asterisk PBX Content-Type: application/dialog-info+xml Content-Length: 245 confirmed [Apr 19 20:52:38] DEBUG[4747] res_pjsip_pubsub.c: evsub 0x7f67fc00dbd8 state ACTIVE event USER sub_tree 0x7f67fc003628 sub_tree state Normal [Apr 19 20:52:38] DEBUG[4747] res_pjsip_pubsub.c: Updating persistence for '103->102' [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to g722 [Apr 19 20:52:38] DEBUG[4807][C-00000001] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:38] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4762] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:39] DEBUG[4762] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:39] DEBUG[4762] acl.c: For destination '192.168.105.105', our source address is '192.168.105.149'. [Apr 19 20:52:39] DEBUG[4762] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:39] DEBUG[4762] netsock2.c: Splitting '192.168.105.105' into... [Apr 19 20:52:39] DEBUG[4762] netsock2.c: ...host '192.168.105.105' and port ''. [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:39] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP response (1692 bytes) from TLS:192.168.105.105:36799 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPje0c6ec8f-f71e-4f37-bc9a-6ce5dfbc5304;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: "103" ;tag=D2B02F28-1995A21D CSeq: 12554 INVITE Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Supported: replaces,100rel User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Allow-Events: conference,talk,hold Accept-Language: en Content-Type: application/sdp Content-Length: 1007 v=0 o=- 1492653158 1492653159 IN IP4 192.168.105.105 s=Polycom IP Phone c=IN IP4 24.214.53.147 t=0 0 a=sendrecv m=audio 10881 RTP/SAVP 9 101 a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:lVyyPs7AHeTcQsyEQ4IYXgwisIQxID3ftC508g20 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv a=ice-pwd:E347brCukuFBKEtCjTl7RA2u/Eyeball a=ice-ufrag:AFxGcE a=rtcp:10882 a=candidate:1 1 UDP 2130706431 192.168.105.105 2224 typ host a=candidate:1 2 UDP 2130706430 192.168.105.105 2225 typ host a=candidate:2 1 TCP 2120810239 192.168.105.105 36006 typ host tcptype passive a=candidate:2 2 TCP 2120810238 192.168.105.105 60105 typ host tcptype passive a=candidate:3 1 TCP 2121072639 192.168.105.105 36006 typ host tcptype active a=candidate:3 2 TCP 2121072638 192.168.105.105 60105 typ host tcptype active a=candidate:4 1 UDP 1694498815 24.214.53.147 10881 typ srflx raddr 192.168.105.105 rport 2424 a=candidate:4 2 UDP 1694498814 24.214.53.147 10882 typ srflx raddr 192.168.105.105 rport 2425 [Apr 19 20:52:39] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:39] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:39] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:39] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:39] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f67fc04d5a8 for Response msg 200/INVITE/cseq=12554 (rdata0x26e8590) [Apr 19 20:52:39] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/103-0000005a on dialog dlg0x7f67fc04d5a8 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONNECTING [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Response is 200 OK [Apr 19 20:52:39] DEBUG[4747] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.105.105' [Apr 19 20:52:39] DEBUG[4747] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.105.105' is 'TLS' [Apr 19 20:52:39] DEBUG[4747] res_pjsip/pjsip_resolver.c: Target '192.168.105.105' is an IP address, skipping resolution [Apr 19 20:52:39] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:39] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:39] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:39] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:39] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to TLS:192.168.105.105:36799 ---> ACK sip:103@192.168.105.105:36799;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPjd1ff04f4-6215-44ba-af33-83ea9976eb05;alias From: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe To: ;tag=D2B02F28-1995A21D Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d CSeq: 12554 ACK Max-Forwards: 70 User-Agent: Asterisk PBX Content-Length: 0 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc0756f8) [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Response is 200 OK [Apr 19 20:52:39] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 103 [Apr 19 20:52:39] DEBUG[4731] devicestate.c: Changing state for PJSIP/103 - state 2 (In use) [Apr 19 20:52:39] DEBUG[4794] app_queue.c: Device 'PJSIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 19 20:52:39] DEBUG[4738] app_queue.c: Extension '103@demo' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 19 20:52:39] VERBOSE[4807][C-00000001] app_dial.c: PJSIP/103-00000001 answered PJSIP/102-00000000 [Apr 19 20:52:39] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/103-00000001 setting read format path: g722 -> slin16 [Apr 19 20:52:39] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/102-00000000 setting write format path: slin16 -> ulaw [Apr 19 20:52:39] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/102-00000000 setting read format path: ulaw -> slin16 [Apr 19 20:52:39] DEBUG[4807][C-00000001] channel.c: Channel PJSIP/103-00000001 setting write format path: slin16 -> g722 [Apr 19 20:52:39] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 102 [Apr 19 20:52:39] DEBUG[4731] devicestate.c: Changing state for PJSIP/102 - state 2 (In use) [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 19 20:52:39] DEBUG[4747] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:39] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:39] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:39] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:39] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:39] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (1419 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---d52c0b0562d0b943 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. From: "102" ;tag=ed7a174d To: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 CSeq: 2 INVITE Server: Asterisk PBX Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 798 v=0 o=- 0 2 IN IP4 192.168.105.149 s=Asterisk c=IN IP4 192.168.105.149 t=0 0 m=audio 11200 RTP/SAVP 0 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:zelqIy2WM3c+3WhryIh/mcIqzqsYTZNmdqTk0E9D/sfQnpsvkSrrvulUa6Q7Dg== a=ice-ufrag:045877512a7c6acc1df7aa333cecf2bf a=ice-pwd:4320c3fd7dbd89782da95acb766def79 a=candidate:Hc0a86995 1 UDP 2130706431 192.168.105.149 11200 typ host a=candidate:S18d63593 1 UDP 1694498815 24.214.53.147 19861 typ srflx raddr 192.168.105.149 rport 11200 a=candidate:Hc0a86995 2 UDP 2130706430 192.168.105.149 11201 typ host a=candidate:S18d63593 2 UDP 1694498814 24.214.53.147 19862 typ srflx raddr 192.168.105.149 rport 11201 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONNECTING [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f67fc01a428) [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONNECTING [Apr 19 20:52:39] DEBUG[4807][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: Cannot use native DAHDI. Must have two channels. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge_native_rtp.c: Bridge '14a6a999-a1d1-4924-9810-6a5f12cf8550' can not use native RTP bridge as two channels are required [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Chose bridge technology simple_bridge [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: calling simple_bridge technology constructor [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: calling simple_bridge technology start [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d698(PJSIP/103-00000001) is joining [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: pushing 0x7f67d400d698(PJSIP/103-00000001) [Apr 19 20:52:39] VERBOSE[4808][C-00000001] bridge_channel.c: Channel PJSIP/103-00000001 joined 'simple_bridge' basic-bridge <14a6a999-a1d1-4924-9810-6a5f12cf8550> [Apr 19 20:52:39] DEBUG[4808][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: Cannot use native DAHDI. Must have two channels. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge_native_rtp.c: Bridge '14a6a999-a1d1-4924-9810-6a5f12cf8550' can not use native RTP bridge as two channels are required [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Chose bridge technology simple_bridge [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550 is already using the new technology. [Apr 19 20:52:39] DEBUG[4808][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d698(PJSIP/103-00000001) is joining simple_bridge technology [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d8c8(PJSIP/102-00000000) is joining [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: pushing 0x7f67d400d8c8(PJSIP/102-00000000) [Apr 19 20:52:39] VERBOSE[4807][C-00000001] bridge_channel.c: Channel PJSIP/102-00000000 joined 'simple_bridge' basic-bridge <14a6a999-a1d1-4924-9810-6a5f12cf8550> [Apr 19 20:52:39] DEBUG[4807][C-00000001] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/103-00000001' is not DAHDI. [Apr 19 20:52:39] DEBUG[4807][C-00000001] dahdi/bridge_native_dahdi.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: Cannot use native DAHDI. Channel 'PJSIP/103-00000001' not compatible. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge_native_rtp.c: Bridge '14a6a999-a1d1-4924-9810-6a5f12cf8550' can not use native RTP bridge as it was forbidden while getting details [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Chose bridge technology simple_bridge [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550 is already using the new technology. [Apr 19 20:52:39] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d8c8(PJSIP/102-00000000) is joining simple_bridge technology [Apr 19 20:52:39] DEBUG[4737] cdr.c: Finalized CDR for PJSIP/103-00000001 - start 1492653158.164332 answer 1492653159.974658 end 1492653159.977863 dispo ANSWERED [Apr 19 20:52:39] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (465 bytes) from TLS:192.168.105.30:56557 ---> ACK sip:192.168.105.149:5061;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---1366f7719f29614d;rport Max-Forwards: 70 Contact: To: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 From: "102" ;tag=ed7a174d Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 2 ACK User-Agent: Z 3.15.40006 rv2.8.20 Content-Length: 0 [Apr 19 20:52:39] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:39] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:39] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:39] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:39] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f680c006088 for Request msg ACK/cseq=2 (rdata0x3d34480) [Apr 19 20:52:39] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 on dialog dlg0x7f680c006088 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The transaction state change event is USER [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONNECTING [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Received request [Apr 19 20:52:39] DEBUG[4747] res_pjsip_session.c: Method is ACK [Apr 19 20:52:40] DEBUG[4808][C-00000001] res_rtp_asterisk.c: 0x7f67fc050a40 -- Probation learning mode pass with source address 192.168.105.105:2424 [Apr 19 20:52:40] VERBOSE[4808][C-00000001] res_rtp_asterisk.c: 0x7f67fc050a40 -- Probation passed - setting RTP source address to 192.168.105.105:2424 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (859 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---b19a7455e56212ee;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=df2eb831 Call-ID: I8n-1nM9v505Ega20rysiQ.. CSeq: 1 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence Allow-Events: presence, kpml, talk Content-Length: 279 open On the phone [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (589 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---80f8c88efbd1b879;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=58334f47 Call-ID: T6NhIBQOg5QwzrsaSobfng.. CSeq: 1 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000024 to use for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4748] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:40] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (559 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---b19a7455e56212ee Call-ID: I8n-1nM9v505Ega20rysiQ.. From: "102" ;tag=df2eb831 To: "102" ;tag=z9hG4bK-524287-1---b19a7455e56212ee CSeq: 1 PUBLISH WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653160/75445e1f7547a1e4fd1073147f4e4b67",opaque="249490ac038b0f7a",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:40] DEBUG[4748] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:40] DEBUG[4748] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:40] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:40] DEBUG[4748] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:40] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:40] DEBUG[4748] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4748] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] VERBOSE[4748] res_pjsip_logger.c: <--- Transmitting SIP response (561 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---80f8c88efbd1b879 Call-ID: T6NhIBQOg5QwzrsaSobfng.. From: "102" ;tag=58334f47 To: "102" ;tag=z9hG4bK-524287-1---80f8c88efbd1b879 CSeq: 1 SUBSCRIBE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653160/75445e1f7547a1e4fd1073147f4e4b67",opaque="3679382e707bda6d",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:40] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (1188 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---2181bcfdf59f3deb;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=df2eb831 Call-ID: I8n-1nM9v505Ega20rysiQ.. CSeq: 2 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653160/75445e1f7547a1e4fd1073147f4e4b67",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="2b80463721ab69f41b1819801fd14727",cnonce="d689ea7101b9efd8b87092d6e18fa0c7",nc=00000001,qop=auth,algorithm=md5,opaque="249490ac038b0f7a" Event: presence Allow-Events: presence, kpml, talk Content-Length: 279 open On the phone [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:40] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653160/75445e1f7547a1e4fd1073147f4e4b67. Actual nonce is 1492653160/75445e1f7547a1e4fd1073147f4e4b67 [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:40] DEBUG[4747] res_pjsip_pubsub.c: Event presence does not match asterisk-devicestate [Apr 19 20:52:40] DEBUG[4747] res_pjsip_pubsub.c: Event presence does not match asterisk-mwi [Apr 19 20:52:40] WARNING[4747] res_pjsip_pubsub.c: No registered publish handler for event presence [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (390 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---2181bcfdf59f3deb Call-ID: I8n-1nM9v505Ega20rysiQ.. From: "102" ;tag=df2eb831 To: "102" ;tag=z9hG4bK-524287-1---2181bcfdf59f3deb CSeq: 2 PUBLISH Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (918 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---5263a7bff4ed52dc;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=58334f47 Call-ID: T6NhIBQOg5QwzrsaSobfng.. CSeq: 2 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653160/75445e1f7547a1e4fd1073147f4e4b67",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="b5bbbe25c490fa42b956e122f7899b9a",cnonce="e14877a9bf441be54a1e4dc3ba4d3549",nc=00000001,qop=auth,algorithm=md5,opaque="3679382e707bda6d" Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000024 to use for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:40] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:40] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653160/75445e1f7547a1e4fd1073147f4e4b67. Actual nonce is 1492653160/75445e1f7547a1e4fd1073147f4e4b67 [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:40] WARNING[4747] res_pjsip_pubsub.c: No registered subscribe handler for event presence.winfo [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:40] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:40] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:40] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (392 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---5263a7bff4ed52dc Call-ID: T6NhIBQOg5QwzrsaSobfng.. From: "102" ;tag=58334f47 To: "102" ;tag=z9hG4bK-524287-1---5263a7bff4ed52dc CSeq: 2 SUBSCRIBE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:40] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:41] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] res_rtp_asterisk.c: Got RTCP report of 80 bytes [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4789] netsock2.c: Splitting '192.168.105.30:33199' into... [Apr 19 20:52:42] DEBUG[4789] netsock2.c: ...host '192.168.105.30' and port '33199'. [Apr 19 20:52:42] DEBUG[4789] netsock2.c: Splitting '192.168.105.149:11201' into... [Apr 19 20:52:42] DEBUG[4789] netsock2.c: ...host '192.168.105.149' and port '11201'. [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 320 vs 160 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] DEBUG[4807][C-00000001] translate.c: Sample size different 160 vs 320 [Apr 19 20:52:42] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (512 bytes) from TLS:192.168.105.105:36799 ---> BYE sip:asterisk@192.168.105.149:5061;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.105:36799;branch=z9hG4bK3665ff52B40C16C7 From: "103" ;tag=D2B02F28-1995A21D To: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe CSeq: 1 BYE Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d Contact: User-Agent: Polycom/5.4.4.3041 PolycomVVX-VVX_600-UA/5.4.4.3041 Accept-Language: en Max-Forwards: 70 Content-Length: 0 [Apr 19 20:52:42] DEBUG[4746] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:42] DEBUG[4746] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:42] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:42] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:42] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f67fc04d5a8 for Request msg BYE/cseq=1 (rdata0x26e8590) [Apr 19 20:52:42] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/103-0000005a on dialog dlg0x7f67fc04d5a8 [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:36799' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '36799'. [Apr 19 20:52:42] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (367 bytes) to TLS:192.168.105.105:36799 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.105.105:36799;rport=36799;received=192.168.105.105;branch=z9hG4bK3665ff52B40C16C7 Call-ID: 83dc3054-2a3f-4fc9-a701-86bad0c13e7d From: "103" ;tag=D2B02F28-1995A21D To: "102" ;tag=914f481e-3ba7-4ed2-893d-bd616c325cbe CSeq: 1 BYE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Received request [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Method is BYE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '103(PJSIP/103-00000001)' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge_channel.c: Setting 0x7f67d400d698(PJSIP/103-00000001) state from:0 to:1 [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: pulling 0x7f67d400d698(PJSIP/103-00000001) [Apr 19 20:52:42] VERBOSE[4808][C-00000001] bridge_channel.c: Channel PJSIP/103-00000001 left 'simple_bridge' basic-bridge <14a6a999-a1d1-4924-9810-6a5f12cf8550> [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d698(PJSIP/103-00000001) is leaving simple_bridge technology [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: dissolving bridge with cause 16(Normal Clearing) [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge_channel.c: Setting 0x7f67d400d8c8(PJSIP/102-00000000) state from:0 to:2 [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: queueing action type:13 sub:1001 [Apr 19 20:52:42] DEBUG[4737] cdr.c: Finalized CDR for PJSIP/102-00000000 - start 1492653158.161780 answer 1492653159.975982 end 1492653162.892112 dispo ANSWERED [Apr 19 20:52:42] DEBUG[4808][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550 is dissolved, not performing smart bridge operation. [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: pulling 0x7f67d400d8c8(PJSIP/102-00000000) [Apr 19 20:52:42] VERBOSE[4807][C-00000001] bridge_channel.c: Channel PJSIP/102-00000000 left 'simple_bridge' basic-bridge <14a6a999-a1d1-4924-9810-6a5f12cf8550> [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge_channel.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: 0x7f67d400d8c8(PJSIP/102-00000000) is leaving simple_bridge technology [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550 is dissolved, not performing smart bridge operation. [Apr 19 20:52:42] DEBUG[4808][C-00000001] channel.c: Hanging up channel 'PJSIP/103-00000001' [Apr 19 20:52:42] DEBUG[4808][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: actually destroying basic bridge, nobody wants it anymore [Apr 19 20:52:42] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 103 [Apr 19 20:52:42] DEBUG[4731] devicestate.c: Changing state for PJSIP/103 - state 1 (Not in use) [Apr 19 20:52:42] DEBUG[4794] app_queue.c: Device 'PJSIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 20:52:42] DEBUG[4738] app_queue.c: Extension '103@demo' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: calling basic bridge destructor [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: calling simple_bridge technology stop [Apr 19 20:52:42] DEBUG[4807][C-00000001] bridge.c: Bridge 14a6a999-a1d1-4924-9810-6a5f12cf8550: calling simple_bridge technology destructor [Apr 19 20:52:42] DEBUG[4737] cdr.c: CDR for PJSIP/103-00000001 is dialed and has no Party B; discarding [Apr 19 20:52:42] DEBUG[4720] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 19 20:52:42] DEBUG[4720] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 19 20:52:42] DEBUG[4807][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Apr 19 20:52:42] DEBUG[4807][C-00000001] pbx.c: Spawn extension (demo,103,1) exited non-zero on 'PJSIP/102-00000000' [Apr 19 20:52:42] VERBOSE[4807][C-00000001] pbx.c: Spawn extension (demo, 103, 1) exited non-zero on 'PJSIP/102-00000000' [Apr 19 20:52:42] DEBUG[4807][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/102-00000000' [Apr 19 20:52:42] DEBUG[4807][C-00000001] pbx_lua.c: Looking up h@demo:1 [Apr 19 20:52:42] DEBUG[4807][C-00000001] channel.c: Hanging up channel 'PJSIP/102-00000000' [Apr 19 20:52:42] DEBUG[4807][C-00000001] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Method is BYE [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.105.30' [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.105.30' is 'TLS' [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Target '192.168.105.30' is an IP address, skipping resolution [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:42] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP request (437 bytes) to TLS:192.168.105.30:56557 ---> BYE sip:102@192.168.105.30:56557;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPj9cc27efa-c3f9-46ce-accd-703394ba345d;alias From: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 To: "102" ;tag=ed7a174d Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 2731 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: Asterisk PBX Content-Length: 0 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102(PJSIP/102-00000000)' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current transaction state is Calling [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 19 20:52:42] DEBUG[4731] devicestate.c: No provider found, checking channel drivers for PJSIP - 102 [Apr 19 20:52:42] DEBUG[4731] devicestate.c: Changing state for PJSIP/102 - state 1 (Not in use) [Apr 19 20:52:42] DEBUG[4794] app_queue.c: Device 'PJSIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 20:52:42] DEBUG[4738] app_queue.c: Extension '102@demo' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: id INTEGER [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: clid VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: src VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: dst VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: dcontext VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: channel VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: dstchannel VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: lastapp VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: lastdata VARCHAR(80) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: start DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: answer DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: end DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: duration INT(11) NOT NULL DEFAULT 0 [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: billsec INT(11) NOT NULL DEFAULT 0 [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: disposition VARCHAR(45) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: amaflags INT(11) NOT NULL DEFAULT 0 [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: accountcode VARCHAR(20) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: uniqueid VARCHAR(32) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: userfield VARCHAR(255) NOT NULL DEFAULT '' [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: Found field: PRIMARY KEY (id) [Apr 19 20:52:42] DEBUG[4737] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"102" <102>','102','103','demo','PJSIP/102-00000000','PJSIP/103-00000001','Dial','PJSIP/103','2017-04-19 20:52:38','2017-04-19 20:52:39','2017-04-19 20:52:42','4','2','ANSWERED','DOCUMENTATION','1492653158.0') [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.105.105' [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.105.105' is 'TLS' [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_resolver.c: Target '192.168.105.105' is an IP address, skipping resolution [Apr 19 20:52:42] DEBUG[4747] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.105.149:5061 [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:42] DEBUG[4747] netsock2.c: Splitting '192.168.105.105:46060' into... [Apr 19 20:52:42] DEBUG[4747] netsock2.c: ...host '192.168.105.105' and port '46060'. [Apr 19 20:52:42] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP request (915 bytes) to TLS:192.168.105.105:46060 ---> NOTIFY sip:103@192.168.105.105:46060;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.105.149:5061;rport;branch=z9hG4bKPj22ec9a87-9b2b-4e53-a378-5e291ed493e7;alias From: ;tag=d73c730b-b0e4-4ca6-a5db-19542753d23f To: "103" ;tag=B2F5829D-8A4A7FD2 Contact: Call-ID: 3e9377a4-84922599-a54d7dce@192.168.105.105 CSeq: 25418 NOTIFY Event: dialog Subscription-State: active;expires=1482 Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: Asterisk PBX Content-Type: application/dialog-info+xml Content-Length: 246 terminated [Apr 19 20:52:42] DEBUG[4747] res_pjsip_pubsub.c: evsub 0x7f67fc00dbd8 state ACTIVE event USER sub_tree 0x7f67fc003628 sub_tree state Normal [Apr 19 20:52:42] DEBUG[4747] res_pjsip_pubsub.c: Updating persistence for '103->102' [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The state change pertains to the endpoint '103()' [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f67fc01a428 [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The transaction state change event is TIMER [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4748] res_pjsip_session.c: Destroying SIP session with endpoint 103 [Apr 19 20:52:42] DEBUG[4748] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01fb58' [Apr 19 20:52:42] DEBUG[4748] rtp_engine.c: Destroyed RTP instance '0x7f67fc01fb58' [Apr 19 20:52:42] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP response (422 bytes) from TLS:192.168.105.30:56557 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS 192.168.105.149:5061;rport=5061;branch=z9hG4bKPj9cc27efa-c3f9-46ce-accd-703394ba345d;alias Contact: To: "102";tag=ed7a174d From: ;tag=da32c49b-fdbe-41d0-ace1-ebb146bcc0c3 Call-ID: L_XX7pEUA1lhlrQYlFoEXg.. CSeq: 2731 BYE User-Agent: Z 3.15.40006 rv2.8.20 Content-Length: 0 [Apr 19 20:52:42] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:42] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:42] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:42] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:42] DEBUG[4746] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f680c006088 for Response msg 200/BYE/cseq=2731 (rdata0x3d34480) [Apr 19 20:52:42] DEBUG[4746] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000034 on dialog dlg0x7f680c006088 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102()' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: There is no transaction involved in this state change [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Response is 200 OK [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The state change pertains to the endpoint '102()' [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current transaction state is Completed [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Received response [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Response is 200 OK [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: BYE received final response code 200 [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The state change pertains to the endpoint '102()' [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f67fc0756f8 [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The current transaction state is Terminated [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The transaction state change event is TIMER [Apr 19 20:52:42] DEBUG[4746] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 19 20:52:42] DEBUG[4747] res_pjsip_session.c: Destroying SIP session with endpoint 102 [Apr 19 20:52:42] DEBUG[4747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f67fc01c198' [Apr 19 20:52:42] DEBUG[4747] rtp_engine.c: Destroyed RTP instance '0x7f67fc01c198' [Apr 19 20:52:43] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (853 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---31793e3ece94e867;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=aa6bf224 Call-ID: nigWwbSM9YvHJS6bzFGJEQ.. CSeq: 1 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence Allow-Events: presence, kpml, talk Content-Length: 273 open Online [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=1 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (589 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---d7aa4be184e67404;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=f81a0909 Call-ID: FxLa0b44IU7POLA0sN0gCA.. CSeq: 1 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000035 to use for Request msg SUBSCRIBE/cseq=1 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4748] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:43] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4748] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4748] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:43] DEBUG[4748] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:43] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:43] DEBUG[4748] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:43] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:43] DEBUG[4748] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4748] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4748] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4748] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] VERBOSE[4748] res_pjsip_logger.c: <--- Transmitting SIP response (561 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---d7aa4be184e67404 Call-ID: FxLa0b44IU7POLA0sN0gCA.. From: "102" ;tag=f81a0909 To: "102" ;tag=z9hG4bK-524287-1---d7aa4be184e67404 CSeq: 1 SUBSCRIBE WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653163/db410d7cfcbbcebeb412e0454f8f8a64",opaque="735fef5a5047d794",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (559 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---31793e3ece94e867 Call-ID: nigWwbSM9YvHJS6bzFGJEQ.. From: "102" ;tag=aa6bf224 To: "102" ;tag=z9hG4bK-524287-1---31793e3ece94e867 CSeq: 1 PUBLISH WWW-Authenticate: Digest realm="switch1.isc.corp.gtinow.com",nonce="1492653163/db410d7cfcbbcebeb412e0454f8f8a64",opaque="3c30759033c318e6",algorithm=md5,qop="auth" Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:43] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (918 bytes) from TLS:192.168.105.30:56557 ---> SUBSCRIBE sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---039b8959f75afa78;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=f81a0909 Call-ID: FxLa0b44IU7POLA0sN0gCA.. CSeq: 2 SUBSCRIBE Expires: 600 Accept: application/watcherinfo+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653163/db410d7cfcbbcebeb412e0454f8f8a64",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="805bec474968793ca74de83fdfa19a65",cnonce="7b11a83b6e555f5c2cc1c047c0cbd35c",nc=00000001,qop=auth,algorithm=md5,opaque="735fef5a5047d794" Event: presence.winfo Allow-Events: presence, kpml, talk Content-Length: 0 [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000035 to use for Request msg SUBSCRIBE/cseq=2 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:43] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653163/db410d7cfcbbcebeb412e0454f8f8a64. Actual nonce is 1492653163/db410d7cfcbbcebeb412e0454f8f8a64 [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:43] WARNING[4747] res_pjsip_pubsub.c: No registered subscribe handler for event presence.winfo [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (392 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---039b8959f75afa78 Call-ID: FxLa0b44IU7POLA0sN0gCA.. From: "102" ;tag=f81a0909 To: "102" ;tag=z9hG4bK-524287-1---039b8959f75afa78 CSeq: 2 SUBSCRIBE Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:43] VERBOSE[4746] res_pjsip_logger.c: <--- Received SIP request (1182 bytes) from TLS:192.168.105.30:56557 ---> PUBLISH sip:102@switch1.isc.corp.gtinow.com;transport=TLS SIP/2.0 Via: SIP/2.0/TLS 192.168.105.30:56557;branch=z9hG4bK-524287-1---213bde2862ae1b06;rport Max-Forwards: 70 Contact: To: "102" From: "102";tag=aa6bf224 Call-ID: nigWwbSM9YvHJS6bzFGJEQ.. CSeq: 2 PUBLISH Expires: 600 Content-Type: application/pidf+xml User-Agent: Z 3.15.40006 rv2.8.20 Authorization: Digest username="102",realm="switch1.isc.corp.gtinow.com",nonce="1492653163/db410d7cfcbbcebeb412e0454f8f8a64",uri="sip:102@switch1.isc.corp.gtinow.com;transport=TLS",response="9c7bff2c86974a686be5413b8a1499eb",cnonce="6fd58e40f69514c2c8e53765e6e547b7",nc=00000001,qop=auth,algorithm=md5,opaque="3c30759033c318e6" Event: presence Allow-Events: presence, kpml, talk Content-Length: 273 open Online [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] DEBUG[4746] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4746] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4746] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003c to use for Request msg PUBLISH/cseq=2 (rdata0x3d34480) [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4747] res_pjsip_endpoint_identifier_user.c: Identified by From username '102' domain 'switch1.isc.corp.gtinow.com' [Apr 19 20:52:43] DEBUG[4747] res_pjsip_authenticator_digest.c: Using default realm 'switch1.isc.corp.gtinow.com' on incoming auth '102'. [Apr 19 20:52:43] DEBUG[4747] res_pjsip_authenticator_digest.c: Calculated nonce 1492653163/db410d7cfcbbcebeb412e0454f8f8a64. Actual nonce is 1492653163/db410d7cfcbbcebeb412e0454f8f8a64 [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port ''. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port ''. [Apr 19 20:52:43] DEBUG[4747] res_pjsip_pubsub.c: Event presence does not match asterisk-devicestate [Apr 19 20:52:43] DEBUG[4747] res_pjsip_pubsub.c: Event presence does not match asterisk-mwi [Apr 19 20:52:43] WARNING[4747] res_pjsip_pubsub.c: No registered publish handler for event presence [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.149:5061' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.149' and port '5061'. [Apr 19 20:52:43] DEBUG[4747] netsock2.c: Splitting '192.168.105.30:56557' into... [Apr 19 20:52:43] DEBUG[4747] netsock2.c: ...host '192.168.105.30' and port '56557'. [Apr 19 20:52:43] VERBOSE[4747] res_pjsip_logger.c: <--- Transmitting SIP response (390 bytes) to TLS:192.168.105.30:56557 ---> SIP/2.0 489 Bad Event Via: SIP/2.0/TLS 192.168.105.30:56557;rport=56557;received=192.168.105.30;branch=z9hG4bK-524287-1---213bde2862ae1b06 Call-ID: nigWwbSM9YvHJS6bzFGJEQ.. From: "102" ;tag=aa6bf224 To: "102" ;tag=z9hG4bK-524287-1---213bde2862ae1b06 CSeq: 2 PUBLISH Server: Asterisk PBX Content-Length: 0 [Apr 19 20:52:48] DEBUG[4752] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 19 20:52:48] DEBUG[4719] threadpool.c: Destroying worker thread 10 [Apr 19 20:52:48] DEBUG[4753] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 19 20:52:48] DEBUG[4719] threadpool.c: Destroying worker thread 11 [Apr 19 20:53:00] DEBUG[4805] cdr.c: CDR Engine termination request received; waiting on messages... [Apr 19 20:53:00] VERBOSE[4805] asterisk.c: Asterisk cleanly ending (0). [Apr 19 20:53:00] VERBOSE[4805] asterisk.c: Executing last minute cleanups [Apr 19 20:53:00] VERBOSE[4805] res_musiconhold.c: Destroying musiconhold processes [Apr 19 20:53:00] DEBUG[4805] res_musiconhold.c: Destroying MOH class 'default' [Apr 19 20:53:00] VERBOSE[4805] manager.c: Manager unregistered action DBGet [Apr 19 20:53:00] VERBOSE[4805] manager.c: Manager unregistered action DBPut [Apr 19 20:53:00] VERBOSE[4805] manager.c: Manager unregistered action DBDel [Apr 19 20:53:00] VERBOSE[4805] manager.c: Manager unregistered action DBDelTree [Apr 19 20:53:00] DEBUG[4805] asterisk.c: Asterisk ending (0).