INVITE sip:3227470203@10.1.25.2 SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 10.1.24.83;branch=z9hG4bK1bdf.fd50c76807d38559bf9aadd57782fa06.0 Via: SIP/2.0/WSS aa3u56aidcac.invalid;rport=40570;received=10.1.5.39;branch=z9hG4bK9685644 Max-Forwards: 16 To: From: ;tag=j98sda51q5 Call-ID: f10dnnv9a7l9rg52s9t7 CSeq: 1579 INVITE Proxy-Authorization: Digest algorithm=MD5, username="1510909667:torrey", realm="voxbone.com", nonce="Wg6kkloOo2Yd86ubP57T8hdSUxnaffMh", uri="sip:3227470203@voxout.voxbone.com", response="b6dd8b865ac4b3cb94c834600f552816", qop=auth, cnonce="a11dqhs7ht6c", nc=00000001 X-Voxbone-Pop: DEV Contact: Content-Type: application/sdp Session-Expires: 3600 Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER Supported: timer,ice,replaces,outbound User-Agent: JsSIP 0.7.9 Content-Length: 1826 v=0 o=- 4350598595259096424 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE audio a=msid-semantic: WMS 5Obg4hjTy464JItJH6Dn3cDstDXHA6ecUISF m=audio 56458 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 50.97.253.78 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:3260304948 1 udp 2122260224 10.1.5.39 45743 typ host generation 0 network-id 1 a=candidate:2362946244 1 tcp 1518280447 10.1.5.39 9 typ host tcptype active generation 0 network-id 1 a=candidate:2161750204 1 udp 1686052607 37.19.10.33 45743 typ srflx raddr 10.1.5.39 rport 45743 generation 0 network-id 1 a=candidate:3790272225 1 udp 25108991 50.97.253.78 56458 typ relay raddr 37.19.10.33 rport 60530 generation 0 network-id 1 a=candidate:3790272225 1 udp 25108735 50.97.253.78 54830 typ relay raddr 37.19.10.33 rport 54870 generation 0 network-id 1 a=ice-ufrag:QVUk a=ice-pwd:Fwk/p+zM0AY5RWI10lmo1v9R a=ice-options:trickle a=fingerprint:sha-256 6C:B3:9D:2C:78:77:92:97:1D:A1:BD:49:49:A3:34:3D:E1:81:B3:15:88:BB:C9:27:4F:6D:5F:40:D2:55:62:0F a=setup:actpass a=mid:audio a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=sendrecv a=rtcp-mux a=rtpmap:111 opus/48000/2 a=rtcp-fb:111 transport-cc a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=ssrc:1548351632 cname:kSkaXHoHEHo8vBJT a=ssrc:1548351632 msid:5Obg4hjTy464JItJH6Dn3cDstDXHA6ecUISF 73a302f2-e28c-4f4c-bb0f-60c7fb264503 a=ssrc:1548351632 mslabel:5Obg4hjTy464JItJH6Dn3cDstDXHA6ecUISF a=ssrc:1548351632 label:73a302f2-e28c-4f4c-bb0f-60c7fb264503 [Nov 17 08:52:54] DEBUG[30213] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1579 (rdata0x7f3f7009bce8) [Nov 17 08:52:54] DEBUG[30213] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002c to use for Request msg INVITE/cseq=1579 (rdata0x7f3f7009bce8) [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:54] DEBUG[1230] acl.c: 10.1.25.3:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.82.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.82.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500::d6ae:52ff:feb5:c60f]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.82.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500::d6ae:52ff:feb3:179f]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.86.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.86.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:4000:0:21e:c9ff:feab:959d]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.86.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:4000:0:21e:c9ff:feab:93db]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.83.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.83.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:80:0:1618:77ff:fe33:835c]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.83.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:80:0:1618:77ff:fe33:8449]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 10.1.24.201:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 10.1.24.81:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 10.1.24.82:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 10.1.24.83:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.84.179:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.84.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:2001:0:1618:77ff:fe2a:1231]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.84.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:2001:0:1618:77ff:fe2a:311c]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.85.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.85.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:2000:0:1618:77ff:fe2a:fd3]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.85.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: [2a03:b500:2000:0:1618:77ff:fe2a:151b]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.82.250:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] acl.c: 81.201.83.110:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'ast13vcc01' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'bebr1ser' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'bebr1ser01' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'bebr1ser01v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'bebr1ser02' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'bebr1ser02v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'cnhk1ser' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'cnhk1ser01' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'cnhk1ser01v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'cnhk1ser02' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'cnhk1ser02v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'defr1ser' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'defr1ser01' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'defr1ser01v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'defr1ser02' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'defr1ser02v6' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'srnd0ser' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'srnd0ser01' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 does not match identify 'srnd0ser02' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.83:5060 matches identify 'srnd0ser11' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id') = 'srnd0ser11' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint srnd0ser11 [Nov 17 08:52:54] DEBUG[1230] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 17 08:52:54] DEBUG[1230] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 17 08:52:54] DEBUG[1230] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002c to use for Request msg INVITE/cseq=1579 (rdata0x7f3f701d00a8) [Nov 17 08:52:54] VERBOSE[1230] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '10.1.25.2' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 17 08:52:54] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP response (511 bytes) to UDP:10.1.24.83:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.24.83;rport=5060;received=10.1.24.83;branch=z9hG4bK1bdf.fd50c76807d38559bf9aadd57782fa06.0 Via: SIP/2.0/WSS aa3u56aidcac.invalid;rport=40570;received=10.1.5.39;branch=z9hG4bK9685644 Record-Route: Record-Route: Call-ID: f10dnnv9a7l9rg52s9t7 From: ;tag=j98sda51q5 To: CSeq: 1579 INVITE Server: Vox Callcontrol Content-Length: 0 [Nov 17 08:52:54] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 17 08:52:54] DEBUG[1230] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f3f78032440' [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Allocated port 11126 for RTP instance '0x7f3f78032440' [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Creating ICE session [::]:11126 (11126) for RTP instance '0x7f3f78032440' [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: RTP instance '0x7f3f78032440' is setup and ready to go [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f3f78032440' [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f3f78032440' [Nov 17 08:52:54] VERBOSE[1230] res_rtp_asterisk.c: DTLS ECDH initialized (secp256r1), faster PFS enabled [Nov 17 08:52:54] DEBUG[1230] sdp_srtp.c: local_key64 Tka9IrgqOWvoYQcN/qeqZD4HKBUDGHMEOs75JGO4 len 40 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 111 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 103 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 104 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 106 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 105 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 13 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Setting tx payload type 112 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Don't have a default tx payload type 113 format for m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Don't have a default tx payload type 126 format for m type on 0x7f3f5b0234f0 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 0 (0x7f3f78018208) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 8 (0x7f3f78018188) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 9 (0x7f3f780181c8) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 13 (0x7f3f780a1b78) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 103 (0x224c9f8) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 104 (0x224ca38) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 105 (0x224ca78) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 106 (0x224cab8) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 110 (0x224caf8) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 111 (0x7f3f78006978) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 112 (0x224cb78) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] rtp_engine.c: Copying payload 126 (0x7f3f7801d0d8) from 0x7f3f5b0234f0 to 0x7f3f78032608 [Nov 17 08:52:54] DEBUG[1230] res_pjsip_session.c: Media stream 'audio' handled by audio [Nov 17 08:52:54] DEBUG[1230] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f78032440' [Nov 17 08:52:54] DEBUG[1230] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Nov 17 08:52:54] DEBUG[1230] res_pjsip_session.c: Method is INVITE [Nov 17 08:52:54] DEBUG[30187] threadpool.c: Increasing threadpool stasis-core's size by 1 [Nov 17 08:52:54] DEBUG[1230] channel.c: Channel 0x7f3f78026610 'PJSIP/srnd0ser11-000000a0' allocated [Nov 17 08:52:54] DEBUG[1230] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/srnd0ser11-000000a0 [Nov 17 08:52:54] DEBUG[2427][C-0000009b] pbx.c: Launching 'AGI' [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] pbx.c: Executing [3227470203@voxout-init:1] AGI("PJSIP/srnd0ser11-000000a0", "agi://127.0.0.1:20203/agi_load_balance_handler") in new stack [Nov 17 08:52:54] DEBUG[2427][C-0000009b] res_agi.c: Wow, connected! [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: [ast13sip01] request for VCC node received [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: statement : SELECT ms.ip, ms.max_calls FROM callcontrollocal.machine_status ms WHERE ms.hostname LIKE ? AND ms.service = vcc AND IFNULL(ms.force_alive, ms.is_alive) = 1; [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: selected VCC node (in pop ast13) : 10.1.25.3 [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] res_agi.c: AGI Script agi://127.0.0.1:20203/agi_load_balance_handler completed, returning 0 [Nov 17 08:52:54] DEBUG[2427][C-0000009b] pbx.c: Launching 'NoOp' [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] pbx.c: Executing [3227470203@voxout-init:2] NoOp("PJSIP/srnd0ser11-000000a0", "using VCC node : 10.1.25.3") in new stack [Nov 17 08:52:54] DEBUG[2427][C-0000009b] pbx_variables.c: Expression result is '1' [Nov 17 08:52:54] DEBUG[2427][C-0000009b] pbx.c: Launching 'ExecIf' [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] pbx.c: Executing [3227470203@voxout-init:3] ExecIf("PJSIP/srnd0ser11-000000a0", "1?AGI(agi://10.1.25.3/init-webrtc):AGI(agi://10.1.25.3/init-voxout") in new stack [Nov 17 08:52:54] DEBUG[2427][C-0000009b] res_agi.c: Wow, connected! [Nov 17 08:52:54] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named X-Voxbone-Context. [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] res_agi.c: AGI Script agi://10.1.25.3/init-webrtc completed, returning 0 [Nov 17 08:52:54] DEBUG[2427][C-0000009b] pbx.c: Launching 'Dial' [Nov 17 08:52:54] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@webrtc:1] Dial("PJSIP/srnd0ser11-000000a0", "PJSIP/3227470203@ast13ser,180,b(predial^s^1)") in new stack [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id') = '3227470203@ast13ser' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id') = 'ast13ser' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:54] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 17 08:52:54] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id') = 'voxser' [Nov 17 08:52:54] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:54] DEBUG[1230] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 17 08:52:54] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 17 08:52:55] DEBUG[1230] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel 0x7f3f780e1160 'PJSIP/ast13ser-000000a1' allocated [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Inheriting variable SIP_HEADERS from PJSIP/srnd0ser11-000000a0 to PJSIP/ast13ser-000000a1. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Inheriting variable SIP_CODEC_OUTBOUND_ORDER_VIDEO from PJSIP/srnd0ser11-000000a0 to PJSIP/ast13ser-000000a1. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Inheriting variable SIP_CODEC_OUTBOUND_ORDER_AUDIO from PJSIP/srnd0ser11-000000a0 to PJSIP/ast13ser-000000a1. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Inheriting variable __CALL_CONTROL_DIAL from PJSIP/srnd0ser11-000000a0 to PJSIP/ast13ser-000000a1. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: Gosub args:predial,s,1 new_args:predial,s,1 [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] app_stack.c: PJSIP/ast13ser-000000a1 Internal Gosub(predial,s,1) start [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: PJSIP/ast13ser-000000a1 Original location: default,s,1 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: Channel PJSIP/ast13ser-000000a1 has no datastore, so we're allocating one. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: Gosub exited with status 0 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'NoOp' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:1] NoOp("PJSIP/ast13ser-000000a1", "Invoking Pre-Dial") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx_variables.c: Expression result is '1' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'While' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:2] While("PJSIP/ast13ser-000000a1", "1") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'NoOp' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Set' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Set' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'EndWhile' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:6] EndWhile("PJSIP/ast13ser-000000a1", "") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'While' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:2] While("PJSIP/ast13ser-000000a1", "1") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'NoOp' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'EndWhile' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:6] EndWhile("PJSIP/ast13ser-000000a1", "") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx_variables.c: Function POP(SIP_HEADERS,\t) result is '(null)' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx_variables.c: Function SET(SIP_HEADER=) result is '' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx_variables.c: Expression result is '0' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'While' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:2] While("PJSIP/ast13ser-000000a1", "0") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Set' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:7] Set("PJSIP/ast13ser-000000a1", "PJSIP_MEDIA_OFFER(audio)=g722,opus,speex16,speex32,alaw,ulaw,speex,g723,g729") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Set' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:8] Set("PJSIP/ast13ser-000000a1", "PJSIP_MEDIA_OFFER(video)=") in new stack [Nov 17 08:52:55] WARNING[1230] format_cap.c: Cannot allow unknown format '' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Set' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:9] Set("PJSIP/ast13ser-000000a1", "CHANNEL(hangup_handler_push)=hdlr_hangup_stats,s,1") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: Gosub args:hdlr_hangup_stats,s,1 new_args:hdlr_hangup_stats,s,1 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] pbx.c: Launching 'Return' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] pbx.c: Executing [s@predial:10] Return("PJSIP/ast13ser-000000a1", "") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: Spawn extension (default,s,1) exited with -1 on 'PJSIP/ast13ser-000000a1' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] app_stack.c: Spawn extension (default, s, 1) exited non-zero on 'PJSIP/ast13ser-000000a1' [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] app_stack.c: PJSIP/ast13ser-000000a1 Internal Gosub(predial,s,1) complete GOSUB_RETVAL= [Nov 17 08:52:55] DEBUG[2427][C-0000009b] app_stack.c: PJSIP/ast13ser-000000a1 Ending location: default,s,1 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Allocated port 12238 for RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Creating ICE session [::]:12238 (12238) for RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: RTP instance '0x7f3f78035890' is setup and ready to go [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is INVITE [Nov 17 08:52:55] DEBUG[1230] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 10.1.25.2:5060 [Nov 17 08:52:55] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP request (1300 bytes) to UDP:10.1.24.201:5060 ---> INVITE sip:3227470203@10.1.24.201 SIP/2.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: Contact: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 CSeq: 14 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Remote-Party-ID: ;privacy=off;screen=no Max-Forwards: 70 User-Agent: Vox Callcontrol Content-Type: application/sdp Content-Length: 495 v=0 o=- 1236968581 1236968581 IN IP4 10.1.25.2 s=session c=IN IP4 10.1.25.2 t=0 0 m=audio 12238 RTP/AVP 9 107 117 119 8 0 110 4 18 101 a=rtpmap:9 G722/8000 a=rtpmap:107 opus/48000/2 a=fmtp:107 useinbandfec=1 a=rtpmap:117 speex/16000 a=rtpmap:119 speex/32000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:110 speex/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] app_dial.c: Called PJSIP/3227470203@ast13ser [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting write format path: opus -> opus [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting read format path: opus -> opus [Nov 17 08:52:55] VERBOSE[30213] res_pjsip_logger.c: <--- Received SIP response (346 bytes) from UDP:10.1.24.201:5060 ---> SIP/2.0 100 Trying to Route Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 CSeq: 14 INVITE Server: VoxSER Load Balancer Content-Length: 0 [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f3f700ae6c8 for Response msg 100/INVITE/cseq=14 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast13ser-00000250 associated with dialog dlg0x7f3f700ae6c8 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Received response [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Response is 100 Trying to Route [Nov 17 08:52:55] VERBOSE[30213] res_pjsip_logger.c: <--- Received SIP request (1550 bytes) from UDP:10.1.24.201:5060 ---> INVITE sip:3227470203@10.1.25.2:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.1.24.201;branch=z9hG4bK3e77.12e9b7a597d919e26e3087a3f1b59807.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: Contact: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 CSeq: 14 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Remote-Party-ID: ;privacy=off;screen=no Max-Forwards: 15 User-Agent: Vox Callcontrol Content-Type: application/sdp Content-Length: 495 v=0 o=- 1236968581 1236968581 IN IP4 10.1.25.2 s=session c=IN IP4 10.1.25.2 t=0 0 m=audio 12238 RTP/AVP 9 107 117 119 8 0 110 4 18 101 a=rtpmap:9 G722/8000 a=rtpmap:107 opus/48000/2 a=fmtp:107 useinbandfec=1 a=rtpmap:117 speex/16000 a=rtpmap:119 speex/32000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:110 speex/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=14 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002d to use for Request msg INVITE/cseq=14 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:55] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 17 08:52:55] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 17 08:52:55] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:55] DEBUG[1230] acl.c: 10.1.25.3:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.82.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.82.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500::d6ae:52ff:feb5:c60f]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.82.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500::d6ae:52ff:feb3:179f]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.86.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.86.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:4000:0:21e:c9ff:feab:959d]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.86.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:4000:0:21e:c9ff:feab:93db]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.83.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.83.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:80:0:1618:77ff:fe33:835c]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.83.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:80:0:1618:77ff:fe33:8449]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 10.1.24.201:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 10.1.24.81:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 10.1.24.82:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 10.1.24.83:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.84.179:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.84.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:2001:0:1618:77ff:fe2a:1231]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.84.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:2001:0:1618:77ff:fe2a:311c]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.85.19:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.85.17:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:2000:0:1618:77ff:fe2a:fd3]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.85.18:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: [2a03:b500:2000:0:1618:77ff:fe2a:151b]:0/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff]:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.82.250:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] acl.c: 81.201.83.110:0/255.255.255.255:0 sense 0 appended to ACL [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'ast13vcc01' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'bebr1ser' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'bebr1ser01' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'bebr1ser01v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'bebr1ser02' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'bebr1ser02v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'cnhk1ser' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'cnhk1ser01' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'cnhk1ser01v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'cnhk1ser02' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'cnhk1ser02v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'defr1ser' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'defr1ser01' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'defr1ser01v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'defr1ser02' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 does not match identify 'defr1ser02v6' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Source address 10.1.24.201:5060 matches identify 'srnd0ser' [Nov 17 08:52:55] DEBUG[1230] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:55] DEBUG[1230] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:55] DEBUG[1230] res_config_odbc.c: Parameter 1 ('id') = 'srnd0ser' [Nov 17 08:52:55] DEBUG[1230] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:55] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:55] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:55] DEBUG[1230] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[1230] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint srnd0ser [Nov 17 08:52:55] DEBUG[1230] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 17 08:52:55] DEBUG[1230] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 17 08:52:55] DEBUG[1230] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002d to use for Request msg INVITE/cseq=14 (rdata0x7f3f701d2098) [Nov 17 08:52:55] VERBOSE[1230] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '10.1.25.2' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 17 08:52:55] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP response (532 bytes) to UDP:10.1.24.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.24.201;rport=5060;received=10.1.24.201;branch=z9hG4bK3e77.12e9b7a597d919e26e3087a3f1b59807.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b Record-Route: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: CSeq: 14 INVITE Server: Vox Callcontrol Content-Length: 0 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Allocated port 16680 for RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Creating ICE session [::]:16680 (16680) for RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: RTP instance '0x7f3f7801bc50' is setup and ready to go [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 107 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 117 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 119 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f3f5b0234f0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 0 (0x7f3f7805c558) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 4 (0x7f3f7800a6b8) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 8 (0x7f3f7802c4d8) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 9 (0x7f3f7806d7e8) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 18 (0x7f3f7800a738) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 101 (0x7f3f7800a6f8) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 107 (0x7f3f78089a18) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 110 (0x7f3f78010778) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 117 (0x7f3f78089918) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 119 (0x7f3f78089958) from 0x7f3f5b0234f0 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Media stream 'audio' handled by audio [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is INVITE [Nov 17 08:52:55] DEBUG[1230] channel.c: Channel 0x7f3f7801c2e0 'PJSIP/srnd0ser-000000a2' allocated [Nov 17 08:52:55] DEBUG[1230] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/srnd0ser-000000a2 [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'AGI' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [3227470203@default:1] AGI("PJSIP/srnd0ser-000000a2", "agi://127.0.0.1:20203/agi_load_balance_handler") in new stack [Nov 17 08:52:55] DEBUG[2430][C-0000009c] res_agi.c: Wow, connected! [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: [ast13sip01] request for VCC node received [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: statement : SELECT ms.ip, ms.max_calls FROM callcontrollocal.machine_status ms WHERE ms.hostname LIKE ? AND ms.service = vcc AND IFNULL(ms.force_alive, ms.is_alive) = 1; [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] res_agi.c: agi://127.0.0.1:20203/agi_load_balance_handler: selected VCC node (in pop ast13) : 10.1.25.3 [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] res_agi.c: AGI Script agi://127.0.0.1:20203/agi_load_balance_handler completed, returning 0 [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'NoOp' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [3227470203@default:2] NoOp("PJSIP/srnd0ser-000000a2", "using VCC node : 10.1.25.3") in new stack [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'GotoIf' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [3227470203@default:3] GotoIf("PJSIP/srnd0ser-000000a2", "0?voxfax-init,,1:") in new stack [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx_builtins.c: Not taking any branch [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'AGI' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [3227470203@default:4] AGI("PJSIP/srnd0ser-000000a2", "agi://10.1.25.3/init") in new stack [Nov 17 08:52:55] DEBUG[2430][C-0000009c] res_agi.c: Wow, connected! [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named X-SS7-ChannelInfo. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named X-Voxbone-Context. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named P-ASSERTED-IDENTITY. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named PRIVACY. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named P-PREFERRED-IDENTITY. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named Diversion. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_header_funcs.c: There was no header named History-Info. [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] res_agi.c: AGI Script agi://10.1.25.3/init completed, returning 0 [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'Answer' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [echo@ivrs2:1] Answer("PJSIP/srnd0ser-000000a2", "") in new stack [Nov 17 08:52:55] DEBUG[30198] devicestate.c: No provider found, checking channel drivers for PJSIP - srnd0ser [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] acl.c: For destination '10.1.25.2', our source address is '10.1.25.2'. [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3f7801bc50' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 107 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 117 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 119 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 0 (0x7f3f7808fdf8) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 4 (0x7f3f780ab798) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 8 (0x7f3f780bf0b8) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 9 (0x7f3f780ac1c8) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 18 (0x7f3f78029078) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 101 (0x7f3f78029038) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 107 (0x7f3f780a09a8) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 110 (0x7f3f780a0a48) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 117 (0x7f3f780bf0f8) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 119 (0x7f3f780bf138) from 0x7f3f5b023000 to 0x7f3f7801be18 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 17 08:52:55] DEBUG[1230] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 10.1.25.2:5060 [Nov 17 08:52:55] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP response (1302 bytes) to UDP:10.1.24.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.24.201;rport=5060;received=10.1.24.201;branch=z9hG4bK3e77.12e9b7a597d919e26e3087a3f1b59807.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b Record-Route: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: ;tag=9c9030c0-4fa8-4895-a0a7-fc5d335ab4e8 CSeq: 14 INVITE Server: Vox Callcontrol Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, REGISTER, REFER, MESSAGE Supported: timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 471 v=0 o=- 1236968581 1236968583 IN IP4 10.1.25.2 s=session c=IN IP4 10.1.25.2 t=0 0 m=audio 16680 RTP/AVP 8 0 18 110 9 117 119 107 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:110 speex/8000 a=rtpmap:9 G722/8000 a=rtpmap:117 speex/16000 a=rtpmap:119 speex/32000 a=rtpmap:107 opus/48000/2 a=fmtp:107 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 17 08:52:55] VERBOSE[30213] res_pjsip_logger.c: <--- Received SIP response (1186 bytes) from UDP:10.1.24.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPje61d1ab2-68f5-4695-9e5e-e6f8b183dd7b Record-Route: Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: ;tag=9c9030c0-4fa8-4895-a0a7-fc5d335ab4e8 CSeq: 14 INVITE Server: Vox Callcontrol Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, REGISTER, REFER, MESSAGE Supported: timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 471 v=0 o=- 1236968581 1236968583 IN IP4 10.1.25.2 s=session c=IN IP4 10.1.25.2 t=0 0 m=audio 16680 RTP/AVP 8 0 18 110 9 117 119 107 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:110 speex/8000 a=rtpmap:9 G722/8000 a=rtpmap:117 speex/16000 a=rtpmap:119 speex/32000 a=rtpmap:107 opus/48000/2 a=fmtp:107 useinbandfec=1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f3f700ae6c8 for Response msg 200/INVITE/cseq=14 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/ast13ser-00000250 associated with dialog dlg0x7f3f700ae6c8 [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Parameter 1 ('id') = 'srnd0ser' [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] devicestate.c: Changing state for PJSIP/srnd0ser - state 2 (In use) [Nov 17 08:52:55] DEBUG[30246] app_queue.c: Device 'PJSIP/srnd0ser' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is RX_MSG [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Received response [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Response is 200 OK [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] acl.c: For destination '10.1.25.2', our source address is '10.1.25.2'. [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 117 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 119 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 107 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f3f5b022dd0 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 0 (0x7f3f780bbc48) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 8 (0x7f3f780a85f8) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 9 (0x7f3f780b46d8) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 18 (0x7f3f780464a8) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 101 (0x7f3f7808e928) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 107 (0x7f3f780177d8) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 110 (0x7f3f7801ce28) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 117 (0x7f3f78010778) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 119 (0x7f3f7805c558) from 0x7f3f5b022dd0 to 0x7f3f78035a58 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP request (476 bytes) to UDP:10.1.24.201:5060 ---> ACK sip:10.1.25.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport;branch=z9hG4bKPj2fa0c962-9ea6-47a3-8d3d-d0c09af7c46b From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: ;tag=9c9030c0-4fa8-4895-a0a7-fc5d335ab4e8 Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 CSeq: 14 ACK Route: Max-Forwards: 70 User-Agent: Vox Callcontrol Content-Length: 0 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Received response [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Response is 200 OK [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] app_dial.c: PJSIP/ast13ser-000000a1 answered PJSIP/srnd0ser11-000000a0 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] chan_pjsip.c: Changing codecs on channel PJSIP/srnd0ser11-000000a0 during OFFER/ANSER exchange. Updating SDP answer [Nov 17 08:52:55] DEBUG[2427][C-0000009b] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f78032440' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Nov 17 08:52:55] DEBUG[30187] threadpool.c: Increasing threadpool stasis-core's size by 1 [Nov 17 08:52:55] DEBUG[30211] threadpool.c: Increasing threadpool SIP's size by 5 [Nov 17 08:52:55] DEBUG[30198] devicestate.c: No provider found, checking channel drivers for PJSIP - ast13ser [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f3f78032440' [Nov 17 08:52:55] DEBUG[1230] acl.c: For destination '50.97.253.78', our source address is '10.1.25.2'. [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3f78032440' [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 111 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 103 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 104 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 106 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 105 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 13 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 110 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Setting tx payload type 112 based on m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Don't have a default tx payload type 113 format for m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Don't have a default tx payload type 126 format for m type on 0x7f3f5b023000 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 0 (0x7f3f78081828) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 8 (0x7f3f780817a8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 9 (0x7f3f780817e8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 13 (0x7f3f780749b8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 103 (0x224c9f8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 104 (0x224ca38) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 105 (0x224ca78) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 106 (0x224cab8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 110 (0x224caf8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 111 (0x7f3f780818e8) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 112 (0x224cb78) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] rtp_engine.c: Copying payload 126 (0x7f3f78057698) from 0x7f3f5b023000 to 0x7f3f78032608 [Nov 17 08:52:55] DEBUG[1230] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting read format path: alaw -> opus [Nov 17 08:52:55] DEBUG[1230] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting write format path: opus -> alaw [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Set role to CONTROLLED (0x7f3f78032440) [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f3f78032440' [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [Nov 17 08:52:55] DEBUG[1230] res_rtp_asterisk.c: Successfully created ICE checklist (0x7f3f78032440) [Nov 17 08:52:55] VERBOSE[30213] res_pjsip_logger.c: <--- Received SIP request (572 bytes) from UDP:10.1.24.201:5060 ---> ACK sip:10.1.25.2:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 10.1.24.201;branch=z9hG4bK3e77.afec6b6ea26c65d2b4ffce76038ca214.0 Via: SIP/2.0/UDP 10.1.25.2:5060;rport=5060;branch=z9hG4bKPj2fa0c962-9ea6-47a3-8d3d-d0c09af7c46b From: ;tag=4795c420-07d5-44d5-9405-80be314be3b6 To: ;tag=9c9030c0-4fa8-4895-a0a7-fc5d335ab4e8 Call-ID: 4a87cea9-493b-4b21-8ca2-eeca30809727 CSeq: 14 ACK Max-Forwards: 15 User-Agent: Vox Callcontrol Content-Length: 0 [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f3f7009fc08 for Request msg ACK/cseq=14 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002d associated with dialog dlg0x7f3f7009fc08 [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Parameter 1 ('id') = 'ast13ser' [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] devicestate.c: Changing state for PJSIP/ast13ser - state 2 (In use) [Nov 17 08:52:55] DEBUG[30246] app_queue.c: Device 'PJSIP/ast13ser' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 17 08:52:55] DEBUG[30198] devicestate.c: No provider found, checking channel drivers for PJSIP - srnd0ser11 [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Reusing ODBC handle 0x249ea80 from class 'callcontrol' [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 17 08:52:55] DEBUG[30198] res_config_odbc.c: Parameter 1 ('id') = 'srnd0ser11' [Nov 17 08:52:55] DEBUG[30198] res_odbc.c: Releasing ODBC handle 0x249ea80 into pool [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'endpoints_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 17 08:52:55] DEBUG[30198] res_sorcery_realtime.c: Filtering out realtime field 'ser_id' from retrieval [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 17 08:52:55] DEBUG[30198] devicestate.c: Changing state for PJSIP/srnd0ser11 - state 2 (In use) [Nov 17 08:52:55] DEBUG[30246] app_queue.c: Device 'PJSIP/srnd0ser11' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 17 08:52:55] DEBUG[1230] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 10.1.25.2:5060 [Nov 17 08:52:55] VERBOSE[1230] res_pjsip_logger.c: <--- Transmitting SIP response (1540 bytes) to UDP:10.1.24.83:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.24.83;rport=5060;received=10.1.24.83;branch=z9hG4bK1bdf.fd50c76807d38559bf9aadd57782fa06.0 Via: SIP/2.0/WSS aa3u56aidcac.invalid;rport=40570;received=10.1.5.39;branch=z9hG4bK9685644 Record-Route: Record-Route: Call-ID: f10dnnv9a7l9rg52s9t7 From: ;tag=j98sda51q5 To: ;tag=4803edb8-92ed-421d-8b15-f8fee9de3f77 CSeq: 1579 INVITE Server: Vox Callcontrol Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, REGISTER, REFER, MESSAGE Supported: timer, replaces, norefersub Session-Expires: 3600;refresher=uac Require: timer Remote-Party-ID: ;privacy=off;screen=no Content-Type: application/sdp Content-Length: 663 v=0 o=- 918248808 5 IN IP4 10.1.25.2 s=session c=IN IP4 10.1.25.2 t=0 0 m=audio 11126 UDP/TLS/RTP/SAVPF 111 126 a=connection:new a=setup:active a=fingerprint:SHA-256 14:9D:17:B8:FF:C6:FD:09:3D:6D:5C:E1:34:1B:FB:56:38:90:B2:6C:71:40:1F:53:B3:79:FA:A3:AC:B9:62:5F a=ice-ufrag:046b9cca60925ac47497f85b4ea6784c a=ice-pwd:6e5b158373e01b5b758743565f5d2d09 a=candidate:He0ebb579 1 UDP 2130706431 fe80::f816:3eff:fe0e:46de 11126 typ host a=candidate:Ha011902 1 UDP 2130706431 10.1.25.2 11126 typ host a=rtpmap:111 opus/48000/2 a=fmtp:111 useinbandfec=1 a=rtpmap:126 telephone-event/8000 a=fmtp:126 0-16 a=ptime:20 a=maxptime:20 a=sendrecv a=rtcp-mux [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b' can not use native RTP bridge as two channels are required [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Chose bridge technology simple_bridge [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: calling simple_bridge technology constructor [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: calling simple_bridge technology start [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Received request [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is ACK [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge_channel.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: 0x7f3f78084e60(PJSIP/ast13ser-000000a1) is joining [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge_channel.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: pushing 0x7f3f78084e60(PJSIP/ast13ser-000000a1) [Nov 17 08:52:55] VERBOSE[2437][C-0000009b] bridge_channel.c: Channel PJSIP/ast13ser-000000a1 joined 'simple_bridge' basic-bridge <3f313ab8-12f4-416d-b52c-0833d08c4d7b> [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b' can not use native RTP bridge as two channels are required [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Chose bridge technology simple_bridge [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b is already using the new technology. [Nov 17 08:52:55] DEBUG[2437][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: 0x7f3f78084e60(PJSIP/ast13ser-000000a1) is joining simple_bridge technology [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_channel.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: 0x7f3f78003550(PJSIP/srnd0ser11-000000a0) is joining [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_channel.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: pushing 0x7f3f78003550(PJSIP/srnd0ser11-000000a0) [Nov 17 08:52:55] VERBOSE[2427][C-0000009b] bridge_channel.c: Channel PJSIP/srnd0ser11-000000a0 joined 'simple_bridge' basic-bridge <3f313ab8-12f4-416d-b52c-0833d08c4d7b> [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b'. Checking compatability for channels 'PJSIP/ast13ser-000000a1' and 'PJSIP/srnd0ser11-000000a0' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b' can not use native RTP bridge as it was forbidden while getting details [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Chose bridge technology simple_bridge [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b is already using the new technology. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b: 0x7f3f78003550(PJSIP/srnd0ser11-000000a0) is joining simple_bridge technology [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting read format path: alaw -> slin48 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/ast13ser-000000a1 setting write format path: slin48 -> opus [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/ast13ser-000000a1 setting read format path: opus -> slin48 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting write format path: slin48 -> alaw [Nov 17 08:52:55] DEBUG[30233] acl.c: For destination '10.1.5.39', our source address is '10.1.25.2'. [Nov 17 08:52:55] DEBUG[30233] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3f78032440' [Nov 17 08:52:55] VERBOSE[30213] res_pjsip_logger.c: <--- Received SIP request (527 bytes) from UDP:10.1.24.83:5060 ---> ACK sip:10.1.25.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.1.24.83;branch=z9hG4bK1bdf.519f9635ddbe8fc87258bdda3e22987e.0 Via: SIP/2.0/WSS aa3u56aidcac.invalid;rport=40570;received=10.1.5.39;branch=z9hG4bK5088992 Max-Forwards: 16 To: ;tag=4803edb8-92ed-421d-8b15-f8fee9de3f77 From: ;tag=j98sda51q5 Call-ID: f10dnnv9a7l9rg52s9t7 CSeq: 1579 ACK Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER Supported: outbound User-Agent: JsSIP 0.7.9 Content-Length: 0 [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f3f800477c8 for Request msg ACK/cseq=1579 (rdata0x7f3f7009bce8) [Nov 17 08:52:55] DEBUG[30213] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000002c associated with dialog dlg0x7f3f800477c8 [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Received request [Nov 17 08:52:55] DEBUG[1230] res_pjsip_session.c: Method is ACK [Nov 17 08:52:55] DEBUG[2427][C-0000009b] res_srtp.c: Adding new policy for SSRC 1901160382 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] res_rtp_asterisk.c: 0x7f3f780ec6a0 -- Probation learning mode pass with source address 10.1.5.39:45743 [Nov 17 08:52:55] DEBUG[2427][C-0000009b] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/srnd0ser11-000000a0' when we're sending 'alaw', switching to match [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting write format path: slin48 -> opus [Nov 17 08:52:55] DEBUG[2427][C-0000009b] channel.c: Channel PJSIP/srnd0ser11-000000a0 setting read format path: slin48 -> opus [Nov 17 08:52:55] DEBUG[2437][C-0000009b] res_rtp_asterisk.c: Ooh, format changed from none to opus [Nov 17 08:52:55] DEBUG[2437][C-0000009b] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f3f78035890' [Nov 17 08:52:55] DEBUG[2430][C-0000009c] res_rtp_asterisk.c: 0x7f3f781151f0 -- Probation learning mode pass with source address 10.1.25.2:12238 [Nov 17 08:52:55] DEBUG[2430][C-0000009c] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/srnd0ser-000000a2' when we're sending 'alaw', switching to match [Nov 17 08:52:55] DEBUG[2430][C-0000009c] channel.c: Channel PJSIP/srnd0ser-000000a2 setting write format path: alaw -> opus [Nov 17 08:52:55] DEBUG[2430][C-0000009c] channel.c: Channel PJSIP/srnd0ser-000000a2 setting read format path: alaw -> opus [Nov 17 08:52:55] DEBUG[2430][C-0000009c] pbx.c: Launching 'Wait' [Nov 17 08:52:55] VERBOSE[2430][C-0000009c] pbx.c: Executing [echo@ivrs2:2] Wait("PJSIP/srnd0ser-000000a2", "4") in new stack [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b'. Checking compatability for channels 'PJSIP/ast13ser-000000a1' and 'PJSIP/srnd0ser11-000000a0' [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge_native_rtp.c: Bridge '3f313ab8-12f4-416d-b52c-0833d08c4d7b' can not use native RTP bridge as it was forbidden while getting details [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Chose bridge technology simple_bridge [Nov 17 08:52:55] DEBUG[2427][C-0000009b] bridge.c: Bridge 3f313ab8-12f4-416d-b52c-0833d08c4d7b is already using the new technology. [Nov 17 08:52:57] DEBUG[2427][C-0000009b] res_rtp_asterisk.c: Got RTCP report of 56 bytes [Nov 17 08:52:59] DEBUG[2430][C-0000009c] pbx.c: Launching 'Playback' [Nov 17 08:52:59] VERBOSE[2430][C-0000009c] pbx.c: Executing [echo@ivrs2:3] Playback("PJSIP/srnd0ser-000000a2", "demo-echotest") in new stack [Nov 17 08:52:59] DEBUG[2430][C-0000009c] channel.c: Channel PJSIP/srnd0ser-000000a2 setting write format path: gsm -> opus [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] DEBUG[2430][C-0000009c] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 17 08:52:59] VERBOSE[2430][C-0000009c] file.c: Playing 'demo-echotest.gsm' (language 'en') [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument [Nov 17 08:52:59] ERROR[2430][C-0000009c] codec_opus.c: Opus: failed to create encoder: invalid argument Nov 17 09:01:10] ERROR[2427][C-0000009b] codec_opus.c: Opus: failed to create encoder: invalid argument