[2017-02-01 18:36:26] Asterisk 13.13.1 built by root @ ats on a x86_64 running Linux on 2017-01-14 10:06:08 UTC [2017-02-01 18:36:29] DEBUG[15284] threadpool.c: Worker thread idle timeout reached. Dying. [2017-02-01 18:36:29] DEBUG[15283] threadpool.c: Worker thread idle timeout reached. Dying. [2017-02-01 18:36:29] DEBUG[15285] threadpool.c: Worker thread idle timeout reached. Dying. [2017-02-01 18:36:29] DEBUG[15282] threadpool.c: Worker thread idle timeout reached. Dying. [2017-02-01 18:36:29] DEBUG[5340] threadpool.c: Destroying worker thread 39558 [2017-02-01 18:36:29] DEBUG[5340] threadpool.c: Destroying worker thread 39559 [2017-02-01 18:36:29] DEBUG[5340] threadpool.c: Destroying worker thread 39560 [2017-02-01 18:36:29] DEBUG[5340] threadpool.c: Destroying worker thread 39557 [2017-02-01 18:36:29] DEBUG[15281] threadpool.c: Worker thread idle timeout reached. Dying. [2017-02-01 18:36:29] DEBUG[5340] threadpool.c: Destroying worker thread 39556 [2017-02-01 18:36:37] DEBUG[15325] http.c: HTTP opening session. Top level [2017-02-01 18:36:37] DEBUG[15325] http.c: HTTP Request URI is /ws [2017-02-01 18:36:37] DEBUG[15325] http.c: match request [ws] with handler [httpstatus] len 10 [2017-02-01 18:36:37] DEBUG[15325] http.c: match request [ws] with handler [static] len 6 [2017-02-01 18:36:37] DEBUG[15325] http.c: match request [ws] with handler [ari] len 3 [2017-02-01 18:36:37] DEBUG[15325] http.c: match request [ws] with handler [ws] len 2 [2017-02-01 18:36:37] DEBUG[15325] http.c: Match made with [ws] [2017-02-01 18:36:37] VERBOSE[15325] res_http_websocket.c: WebSocket connection from '192.168.10.63:37348' for protocol 'sip' accepted using version '13' [2017-02-01 18:36:37] DEBUG[15325] res_pjsip_transport_websocket.c: Found WS transport with write timeout: 100 [2017-02-01 18:36:37] DEBUG[15325] res_pjsip_transport_websocket.c: Write timeout for WS/WSS transports: 100 [2017-02-01 18:36:37] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (506 bytes) from WS:192.168.10.63:37348 ---> REGISTER sip:192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bK1duUypKZFhv2U9MwqLDxUi47Vi4xElde;rport From: ;tag=NuNLD4METD4Hm1wTlrQm To: Contact: "undefined";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 CSeq: 38552 REGISTER Content-Length: 0 Max-Forwards: 70 Organization: TFOMS SK Supported: path [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:37] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=38552 (rdata0x7f36580b8d88) [2017-02-01 18:36:37] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000007d to use for Request msg REGISTER/cseq=38552 (rdata0x7f36580b8d88) [2017-02-01 18:36:37] DEBUG[5340] threadpool.c: Increasing threadpool SIP's size by 5 [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:37] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:37] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (528 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bK1duUypKZFhv2U9MwqLDxUi47Vi4xElde Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 From: ;tag=NuNLD4METD4Hm1wTlrQm To: ;tag=z9hG4bK1duUypKZFhv2U9MwqLDxUi47Vi4xElde CSeq: 38552 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe",opaque="488d6cd36abe5416",algorithm=md5,qop="auth" Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:37] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 528 [2017-02-01 18:36:37] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (783 bytes) from WS:192.168.10.63:37348 ---> REGISTER sip:192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT9oumO3hSrmiseEWpLBqgmGJfw18N1fh;rport From: ;tag=NuNLD4METD4Hm1wTlrQm To: Contact: "undefined";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 CSeq: 38553 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="598",realm="asterisk",nonce="1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe",uri="sip:192.168.1.47",response="759c14a11d5dd2f6ebf4c6db40b602b7",algorithm=md5,cnonce="961cc589dab3632cef8f8aae44b50074",opaque="488d6cd36abe5416",qop=auth,nc=00000001 Organization: TFOMS SK Supported: path [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:37] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=38553 (rdata0x7f36580b8d88) [2017-02-01 18:36:37] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000007d to use for Request msg REGISTER/cseq=38553 (rdata0x7f36580b8d88) [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:37] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:37] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_authenticator_digest.c: Calculated nonce 1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe. Actual nonce is 1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_registrar.c: Matched id '598' to aor '598' [2017-02-01 18:36:37] DEBUG[15211] res_pjsip_registrar.c: Matched aor '598' by To username [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] VERBOSE[15211] res_pjsip_registrar.c: Added contact 'sip:598@192.168.10.63:37348;transport=ws;rtcweb-breaker=yes' to AOR '598' with expiration of 200 seconds [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [2017-02-01 18:36:37] VERBOSE[15216] res_pjsip/pjsip_configuration.c: Contact 598/sip:598@192.168.10.63:37348;transport=ws;rtcweb-breaker=yes has been created [2017-02-01 18:36:37] DEBUG[3102] threadpool.c: Increasing threadpool stasis-core's size by 1 [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15211] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:37] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:37] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (509 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 200 OK Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKT9oumO3hSrmiseEWpLBqgmGJfw18N1fh Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 From: ;tag=NuNLD4METD4Hm1wTlrQm To: ;tag=z9hG4bKT9oumO3hSrmiseEWpLBqgmGJfw18N1fh CSeq: 38553 REGISTER Date: Wed, 01 Feb 2017 15:36:37 GMT Contact: ;expires=199 Supported: path Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:37] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 509 [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] VERBOSE[15216] res_pjsip/pjsip_configuration.c: Endpoint 598 is now Reachable [2017-02-01 18:36:37] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - 598 [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [2017-02-01 18:36:37] VERBOSE[15216] res_pjsip/pjsip_configuration.c: Contact 598/sip:598@192.168.10.63:37348;transport=ws;rtcweb-breaker=yes is now Unknown. RTT: 0.000 msec [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:37] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:37] DEBUG[3340] devicestate.c: Changing state for PJSIP/598 - state 1 (Not in use) [2017-02-01 18:36:37] DEBUG[5857] app_queue.c: Device 'PJSIP/598' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (1598 bytes) from WS:192.168.10.63:37348 ---> INVITE sip:135@192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKsqa9zpqeICtADIzAZigXneKTEiyBPDl2;rport From: ;tag=cFhkIcv84vfgtZARPgh8 To: Contact: "undefined";impi=598;ha1=2f3ec4391873c8af52181e5d7763c8b7 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 CSeq: 22820 INVITE Content-Type: application/sdp Content-Length: 1079 Max-Forwards: 70 Organization: TFOMS SK v=0 o=mozilla...THIS_IS_SDPARTA-51.0.1 878915998764550300 0 IN IP4 127.0.0.1 s=Doubango Telecom - firefox t=0 0 a=sendrecv a=fingerprint:sha-256 EA:00:4F:0F:34:DC:E1:4E:5B:F6:1E:A3:CD:E7:64:88:AF:74:2D:9A:96:F2:05:9D:98:B6:15:3D:56:D3:BD:64 a=ice-options:trickle a=msid-semantic:WMS * m=audio 53278 UDP/TLS/RTP/SAVPF 109 9 0 8 c=IN IP4 192.168.10.63 a=candidate:0 1 UDP 2122252543 192.168.10.63 53278 typ host a=candidate:0 2 UDP 2122252542 192.168.10.63 53279 typ host a=sendrecv a=end-of-candidates a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1 a=ice-pwd:d67ab3a2a1578d38f84cbab47ddfd639 a=ice-ufrag:2cdc89a4 a=mid:sdparta_0 a=msid:{df97f57f-26e7-42df-990b-b03548ea5923} {05aef40c-0ac6-4ab0-9d7b-71cbdef562f0} a=rtcp:53279 IN IP4 192.168.10.63 a=rtcp-mux a=rtpmap:109 opus/48000/2 a=rtpmap:9 G722/8000/1 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=setup:actpass a=ssrc:3360984115 cname:{8acc5211-c800-4076-af97-5f16ac9d04d0} [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=22820 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000089 to use for Request msg INVITE/cseq=22820 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:41] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (526 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKsqa9zpqeICtADIzAZigXneKTEiyBPDl2 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=z9hG4bKsqa9zpqeICtADIzAZigXneKTEiyBPDl2 CSeq: 22820 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1485963401/4f19458daa2669bd25b08c9f9a992d8e",opaque="09fc85e96a898deb",algorithm=md5,qop="auth" Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:41] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 526 [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (355 bytes) from WS:192.168.10.63:37348 ---> ACK sip:135@192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKsqa9zpqeICtADIzAZigXneKTEiyBPDl2;rport From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=z9hG4bKsqa9zpqeICtADIzAZigXneKTEiyBPDl2 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 CSeq: 22820 ACK Content-Length: 0 Max-Forwards: 70 [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=22820 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000089 to use for Request msg ACK/cseq=22820 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:41] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (1879 bytes) from WS:192.168.10.63:37348 ---> INVITE sip:135@192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKMDKaZ3qgk6u4xQnZNECC0u9ODm2ydhw9;rport From: ;tag=cFhkIcv84vfgtZARPgh8 To: Contact: "undefined";impi=598;ha1=2f3ec4391873c8af52181e5d7763c8b7 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 CSeq: 22821 INVITE Content-Type: application/sdp Content-Length: 1079 Max-Forwards: 70 Authorization: Digest username="598",realm="asterisk",nonce="1485963401/4f19458daa2669bd25b08c9f9a992d8e",uri="sip:135@192.168.1.47",response="d516fcccce37ea0d3566895ec251bdc1",algorithm=md5,cnonce="7c65564b9fcfec3d29f3c99ceab5c2f2",opaque="09fc85e96a898deb",qop=auth,nc=00000001 Organization: TFOMS SK v=0 o=mozilla...THIS_IS_SDPARTA-51.0.1 878915998764550300 0 IN IP4 127.0.0.1 s=Doubango Telecom - firefox t=0 0 a=sendrecv a=fingerprint:sha-256 EA:00:4F:0F:34:DC:E1:4E:5B:F6:1E:A3:CD:E7:64:88:AF:74:2D:9A:96:F2:05:9D:98:B6:15:3D:56:D3:BD:64 a=ice-options:trickle a=msid-semantic:WMS * m=audio 53278 UDP/TLS/RTP/SAVPF 109 9 0 8 c=IN IP4 192.168.10.63 a=candidate:0 1 UDP 2122252543 192.168.10.63 53278 typ host a=candidate:0 2 UDP 2122252542 192.168.10.63 53279 typ host a=sendrecv a=end-of-candidates a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1 a=ice-pwd:d67ab3a2a1578d38f84cbab47ddfd639 a=ice-ufrag:2cdc89a4 a=mid:sdparta_0 a=msid:{df97f57f-26e7-42df-990b-b03548ea5923} {05aef40c-0ac6-4ab0-9d7b-71cbdef562f0} a=rtcp:53279 IN IP4 192.168.10.63 a=rtcp-mux a=rtpmap:109 opus/48000/2 a=rtpmap:9 G722/8000/1 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=setup:actpass a=ssrc:3360984115 cname:{8acc5211-c800-4076-af97-5f16ac9d04d0} [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=22821 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000089 to use for Request msg INVITE/cseq=22821 (rdata0x7f36580b8d88) [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:41] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:41] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_authenticator_digest.c: Calculated nonce 1485963401/4f19458daa2669bd25b08c9f9a992d8e. Actual nonce is 1485963401/4f19458daa2669bd25b08c9f9a992d8e [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000089 to use for Request msg INVITE/cseq=22821 (rdata0x7f36580f66e8) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f3658069fd0' [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Allocated port 13860 for RTP instance '0x7f3658069fd0' [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Creating ICE session [::]:13860 (13860) for RTP instance '0x7f3658069fd0' [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.1.47' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.1.47' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.4' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '172.16.155.34' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '172.16.155.34' and port ''. [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: RTP instance '0x7f3658069fd0' is setup and ready to go [2017-02-01 18:36:41] DEBUG[15211] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting 'ats' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host 'ats' and port ''. [2017-02-01 18:36:41] DEBUG[15211] acl.c: Multiple addresses. Using the first only [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f3658069fd0' [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.1.47' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.1.47' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.4' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '172.16.155.34' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '172.16.155.34' and port ''. [2017-02-01 18:36:41] VERBOSE[15211] res_rtp_asterisk.c: DTLS ECDH initialized (automatic), faster PFS enabled [2017-02-01 18:36:41] DEBUG[15211] sdp_srtp.c: local_key64 XauK3m0Rh1Am8shPCu6E6xOHV2NQjKlfe+uFpmFm len 40 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Don't have a default tx payload type 109 format for m type on 0x7f363404d380 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f363404d380 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f363404d380 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f363404d380 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Copying payload 0 (0x7f36580356b8) from 0x7f363404d380 to 0x7f365806a198 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Copying payload 8 (0x7f3658026b38) from 0x7f363404d380 to 0x7f365806a198 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Copying payload 9 (0x7f3658063388) from 0x7f363404d380 to 0x7f365806a198 [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Copying payload 109 (0x7f3658063a08) from 0x7f363404d380 to 0x7f365806a198 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Media stream 'audio' handled by audio [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (329 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 100 Trying Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKMDKaZ3qgk6u4xQnZNECC0u9ODm2ydhw9 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 From: ;tag=cFhkIcv84vfgtZARPgh8 To: CSeq: 22821 INVITE Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:41] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 329 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598()' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is INCOMING [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598()' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current transaction state is Proceeding [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is INCOMING [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Method is INVITE [2017-02-01 18:36:41] DEBUG[15211] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/598-00000599 [2017-02-01 18:36:41] DEBUG[15332][C-000002e5] pbx_variables.c: Result of 'EXTEN' is '135' [2017-02-01 18:36:41] DEBUG[15332][C-000002e5] pbx.c: Launching 'NoOp' [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:41] VERBOSE[15332][C-000002e5] pbx.c: Executing [135@from-internal:1] NoOp("PJSIP/598-00000599", "135") in new stack [2017-02-01 18:36:41] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('CHAN_START',{ts '2017-02-01 18:36:41.619694'},'598','598','','','','135','from-internal','PJSIP/598-00000599','','',3,'','1485963401.3198','1485963401.3198','','','')] [2017-02-01 18:36:41] DEBUG[15332][C-000002e5] pbx_variables.c: Result of 'EXTEN' is '135' [2017-02-01 18:36:41] DEBUG[15332][C-000002e5] pbx.c: Launching 'Dial' [2017-02-01 18:36:41] VERBOSE[15332][C-000002e5] pbx.c: Executing [135@from-internal:2] Dial("PJSIP/598-00000599", "PJSIP/135@mypbx,60") in new stack [2017-02-01 18:36:41] DEBUG[15211] db.c: Unable to find key 'mypbx' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:41] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object 'mypbx' from astdb [2017-02-01 18:36:41] DEBUG[15211] db.c: Unable to find key 'mypbx' in family 'ps_aors/aor' [2017-02-01 18:36:41] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object 'mypbx' from astdb [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f3658025570' [2017-02-01 18:36:41] VERBOSE[15332][C-000002e5] app_dial.c: Called PJSIP/135@mypbx [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Allocated port 14056 for RTP instance '0x7f3658025570' [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Creating ICE session [::]:14056 (14056) for RTP instance '0x7f3658025570' [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.1.47' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.1.47' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.4' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '172.16.155.34' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '172.16.155.34' and port ''. [2017-02-01 18:36:41] DEBUG[15211] rtp_engine.c: RTP instance '0x7f3658025570' is setup and ready to go [2017-02-01 18:36:41] DEBUG[15211] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting 'ats' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host 'ats' and port ''. [2017-02-01 18:36:41] DEBUG[15211] acl.c: Multiple addresses. Using the first only [2017-02-01 18:36:41] DEBUG[15211] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f3658025570' [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.1.47' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.1.47' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.4' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '195.19.212.8' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '195.19.212.8' and port ''. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '172.16.155.34' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '172.16.155.34' and port ''. [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Method is INVITE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 192.168.5.4:5060 [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP request (873 bytes) to UDP:192.168.5.2:5060 ---> INVITE sip:135@192.168.5.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.5.4:5060;rport;branch=z9hG4bKPjf216e6a5-d81b-4afa-b036-7d60cb0ed32b From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: Contact: Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26195 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: TFOMSSK Content-Type: application/sdp Content-Length: 242 v=0 o=CallCenter 251282160 251282160 IN IP4 192.168.5.4 s=Asterisk c=IN IP4 192.168.5.4 t=0 0 m=audio 14056 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is CALLING [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current transaction state is Calling [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is CALLING [2017-02-01 18:36:41] VERBOSE[5345] res_pjsip_logger.c: <--- Received SIP response (533 bytes) from UDP:192.168.5.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.5.4:5060;branch=z9hG4bKPjf216e6a5-d81b-4afa-b036-7d60cb0ed32b;received=192.168.5.4;rport=5060 From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26195 INVITE Server: TFOMS Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:41] DEBUG[5345] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36b40c2a88 for Response msg 100/INVITE/cseq=26195 (rdata0x7f36a0001dd8) [2017-02-01 18:36:41] DEBUG[5345] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/mypbx-000006e8 on dialog dlg0x7f36b40c2a88 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current transaction state is Proceeding [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The transaction state change event is RX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is CALLING [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Received response [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Response is 100 Trying [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:41] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('APP_START',{ts '2017-02-01 18:36:41.637126'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','Dial','PJSIP/135@mypbx,60',3,'','1485963401.3198','1485963401.3198','','','')] [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:41] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('CHAN_START',{ts '2017-02-01 18:36:41.652270'},'','','','','','s','mypbx-context','PJSIP/mypbx-0000059a','','',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:41] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:41] VERBOSE[5345] res_pjsip_logger.c: <--- Received SIP response (549 bytes) from UDP:192.168.5.2:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.5.4:5060;branch=z9hG4bKPjf216e6a5-d81b-4afa-b036-7d60cb0ed32b;received=192.168.5.4;rport=5060 From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: ;tag=as282f9a87 Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26195 INVITE Server: TFOMS Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:41] DEBUG[5345] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:41] DEBUG[5345] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36b40c2a88 for Response msg 180/INVITE/cseq=26195 (rdata0x7f36a0001dd8) [2017-02-01 18:36:41] DEBUG[5345] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/mypbx-000006e8 on dialog dlg0x7f36b40c2a88 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is EARLY [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is RX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Received response [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Response is 180 Ringing [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current transaction state is Proceeding [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The transaction state change event is RX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is EARLY [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Received response [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Response is 180 Ringing [2017-02-01 18:36:41] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - mypbx [2017-02-01 18:36:41] VERBOSE[15332][C-000002e5] app_dial.c: PJSIP/mypbx-0000059a is ringing [2017-02-01 18:36:41] DEBUG[3340] db.c: Unable to find key 'mypbx' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:41] DEBUG[3340] res_sorcery_astdb.c: Failed to retrieve object 'mypbx' from astdb [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [2017-02-01 18:36:41] DEBUG[3340] devicestate.c: Changing state for PJSIP/mypbx - state 6 (Ringing) [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:41] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:41] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - 598 [2017-02-01 18:36:41] DEBUG[5857] app_queue.c: Device 'PJSIP/mypbx' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2017-02-01 18:36:41] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (531 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 180 Ringing Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKMDKaZ3qgk6u4xQnZNECC0u9ODm2ydhw9 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=ca7d8bc4-fdbd-4b0f-983d-754e7759f698 CSeq: 22821 INVITE Server: TFOMSSK Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Content-Length: 0 [2017-02-01 18:36:41] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 531 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is EARLY [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current transaction state is Proceeding [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:41] DEBUG[15211] res_pjsip_session.c: The current inv state is EARLY [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:41] DEBUG[3340] devicestate.c: Changing state for PJSIP/598 - state 2 (In use) [2017-02-01 18:36:41] DEBUG[5857] app_queue.c: Device 'PJSIP/598' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2017-02-01 18:36:42] VERBOSE[5345] res_pjsip_logger.c: <--- Received SIP response (811 bytes) from UDP:192.168.5.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.5.4:5060;branch=z9hG4bKPjf216e6a5-d81b-4afa-b036-7d60cb0ed32b;received=192.168.5.4;rport=5060 From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: ;tag=as282f9a87 Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26195 INVITE Server: TFOMS Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Content-Length: 234 v=0 o=root 1794417419 1794417419 IN IP4 192.168.5.2 s=Asterisk PBX 1.6.2.6 c=IN IP4 192.168.5.2 t=0 0 m=audio 10020 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv [2017-02-01 18:36:42] DEBUG[5345] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:42] DEBUG[5345] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:42] DEBUG[5345] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:42] DEBUG[5345] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:42] DEBUG[5345] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36b40c2a88 for Response msg 200/INVITE/cseq=26195 (rdata0x7f36a0001dd8) [2017-02-01 18:36:42] DEBUG[5345] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/mypbx-000006e8 on dialog dlg0x7f36b40c2a88 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONNECTING [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is RX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Received response [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Response is 200 OK [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.5.2' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.5.2' and port ''. [2017-02-01 18:36:42] DEBUG[15211] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2017-02-01 18:36:42] DEBUG[15211] acl.c: For destination '192.168.5.2', our source address is '192.168.5.4'. [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3658025570' [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f363404cab0 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f363404cab0 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 0 (0x7f3658022f48) from 0x7f363404cab0 to 0x7f3658025738 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 101 (0x7f36580ff608) from 0x7f363404cab0 to 0x7f3658025738 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:42] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP request (371 bytes) to UDP:192.168.5.2:5060 ---> ACK sip:135@192.168.5.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.5.4:5060;rport;branch=z9hG4bKPja87adfb7-233f-44c1-a154-791fce10d5cb From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: ;tag=as282f9a87 Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26195 ACK Max-Forwards: 70 User-Agent: TFOMSSK Content-Length: 0 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f365c009a38) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONFIRMED [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current transaction state is Terminated [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The transaction state change event is RX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONFIRMED [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Received response [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Response is 200 OK [2017-02-01 18:36:42] VERBOSE[15332][C-000002e5] app_dial.c: PJSIP/mypbx-0000059a answered PJSIP/598-00000599 [2017-02-01 18:36:42] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - mypbx [2017-02-01 18:36:42] DEBUG[3340] db.c: Unable to find key 'mypbx' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:42] DEBUG[3340] res_sorcery_astdb.c: Failed to retrieve object 'mypbx' from astdb [2017-02-01 18:36:42] DEBUG[3340] devicestate.c: Changing state for PJSIP/mypbx - state 2 (In use) [2017-02-01 18:36:42] DEBUG[3102] threadpool.c: Increasing threadpool stasis-core's size by 1 [2017-02-01 18:36:42] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - 598 [2017-02-01 18:36:42] DEBUG[5857] app_queue.c: Device 'PJSIP/mypbx' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [2017-02-01 18:36:42] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('ANSWER',{ts '2017-02-01 18:36:42.850442'},'','135','','','','135','mypbx-context','PJSIP/mypbx-0000059a','AppDial','(Outgoing Line)',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:42] DEBUG[15211] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2017-02-01 18:36:42] DEBUG[15211] acl.c: For destination '192.168.10.63', our source address is '192.168.1.47'. [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3658069fd0' [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Don't have a default tx payload type 109 format for m type on 0x7f363404cd50 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f363404cd50 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f363404cd50 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f363404cd50 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 0 (0x7f36580fa328) from 0x7f363404cd50 to 0x7f365806a198 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 8 (0x7f3658007e08) from 0x7f363404cd50 to 0x7f365806a198 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 9 (0x7f36580318a8) from 0x7f363404cd50 to 0x7f365806a198 [2017-02-01 18:36:42] DEBUG[15211] rtp_engine.c: Copying payload 109 (0x7f36580f5878) from 0x7f363404cd50 to 0x7f365806a198 [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Set role to CONTROLLED (0x7f3658069fd0) [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Resetting ICE for RTP instance '0x7f3658069fd0' [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Nevermind. ICE isn't ready for a reset [2017-02-01 18:36:42] DEBUG[15211] res_rtp_asterisk.c: Successfully created ICE checklist (0x7f3658069fd0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Method is INVITE, Response is 200 OK [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:42] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (1169 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 200 OK Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKMDKaZ3qgk6u4xQnZNECC0u9ODm2ydhw9 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=ca7d8bc4-fdbd-4b0f-983d-754e7759f698 CSeq: 22821 INVITE Server: TFOMSSK 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: 561 v=0 o=- 3049572508 2 IN IP4 195.19.212.8 s=Asterisk c=IN IP4 195.19.212.8 t=0 0 m=audio 13860 UDP/TLS/RTP/SAVPF 0 a=connection:new a=setup:active a=fingerprint:SHA-256 4B:75:D9:2E:B5:57:6C:44:A2:CE:E4:63:C7:30:38:7B:21:9F:0E:2A:10:61:F9:97:63:51:66:C4:D2:F7:07:90 a=ice-ufrag:189301b03957c5e07d1768c42d812136 a=ice-pwd:7ac7f6b709ff9ace6f34c8e16eb83d14 a=candidate:Hc313d408 1 UDP 2130706431 195.19.212.8 13860 typ host a=candidate:Hc313d408 2 UDP 2130706430 195.19.212.8 13861 typ host a=rtpmap:0 PCMU/8000 a=ptime:20 a=maxptime:150 a=sendrecv [2017-02-01 18:36:42] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 1169 [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONNECTING [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is TX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f36c00f5098) [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current transaction state is Completed [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONNECTING [2017-02-01 18:36:42] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:42] DEBUG[3340] devicestate.c: Changing state for PJSIP/598 - state 2 (In use) [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge_native_rtp.c: Bridge 'a46083d6-1224-449b-a3cc-265771cf0f0c' can not use native RTP bridge as two channels are required [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Chose bridge technology simple_bridge [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: calling simple_bridge technology constructor [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: calling simple_bridge technology start [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019290(PJSIP/mypbx-0000059a) is joining [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: pushing 0x7f36b8019290(PJSIP/mypbx-0000059a) [2017-02-01 18:36:42] VERBOSE[15334][C-000002e5] bridge_channel.c: Channel PJSIP/mypbx-0000059a joined 'simple_bridge' basic-bridge [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Bridge technology softmix does not have any capabilities we want. [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge_native_rtp.c: Bridge 'a46083d6-1224-449b-a3cc-265771cf0f0c' can not use native RTP bridge as two channels are required [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Chose bridge technology simple_bridge [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c is already using the new technology. [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019290(PJSIP/mypbx-0000059a) is joining simple_bridge technology [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019430(PJSIP/598-00000599) is joining [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: pushing 0x7f36b8019430(PJSIP/598-00000599) [2017-02-01 18:36:42] VERBOSE[15332][C-000002e5] bridge_channel.c: Channel PJSIP/598-00000599 joined 'simple_bridge' basic-bridge [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge technology softmix does not have any capabilities we want. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge_native_rtp.c: Bridge 'a46083d6-1224-449b-a3cc-265771cf0f0c' can not use native RTP bridge as it was forbidden while getting details [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Chose bridge technology simple_bridge [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c is already using the new technology. [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019430(PJSIP/598-00000599) is joining simple_bridge technology [2017-02-01 18:36:42] DEBUG[3707] cdr.c: Finalized CDR for PJSIP/mypbx-0000059a - start 1485963401.620248 answer 1485963402.850416 end 1485963402.851319 dispo ANSWERED [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:42] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('ANSWER',{ts '2017-02-01 18:36:42.871542'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','Dial','PJSIP/135@mypbx,60',3,'','1485963401.3198','1485963401.3198','','','')] [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:42] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('BRIDGE_ENTER',{ts '2017-02-01 18:36:42.888613'},'','135','','','','','mypbx-context','PJSIP/mypbx-0000059a','AppDial','(Outgoing Line)',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:42] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (775 bytes) from WS:192.168.10.63:37348 ---> ACK sip:192.168.10.63:37348;transport=WS SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKTz1a76Jhxk9bqimnp5lN;rport From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=ca7d8bc4-fdbd-4b0f-983d-754e7759f698 Contact: "undefined" Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 CSeq: 22821 ACK Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="598",realm="asterisk",nonce="1485963401/4f19458daa2669bd25b08c9f9a992d8e",uri="sip:192.168.10.63:37348;transport=WS",response="d8e50e7f7d1233c135f7223c68b8727c",algorithm=md5,cnonce="7c65564b9fcfec3d29f3c99ceab5c2f2",opaque="09fc85e96a898deb",qop=auth,nc=00000002 Organization: TFOMS SK [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:42] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36c00e0288 for Request msg ACK/cseq=22821 (rdata0x7f36580b8d88) [2017-02-01 18:36:42] DEBUG[15211] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000089 on dialog dlg0x7f36c00e0288 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current transaction state is Terminated [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The transaction state change event is USER [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONNECTING [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: The current inv state is CONFIRMED [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Received request [2017-02-01 18:36:42] DEBUG[15211] res_pjsip_session.c: Method is ACK [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:42] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('BRIDGE_ENTER',{ts '2017-02-01 18:36:42.899960'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','Dial','PJSIP/135@mypbx,60',3,'','1485963401.3198','1485963401.3198','PJSIP/mypbx-0000059a','','')] [2017-02-01 18:36:42] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:42] DEBUG[15334][C-000002e5] res_rtp_asterisk.c: 0x7f36580e6d20 -- Probation learning mode pass with source address 192.168.5.2:10020 [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2017-02-01 18:36:42] DEBUG[15332][C-000002e5] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f3658069fd0' [2017-02-01 18:36:43] DEBUG[5616] netsock2.c: Splitting '212.96.122.148' into... [2017-02-01 18:36:43] DEBUG[5616] netsock2.c: ...host '212.96.122.148' and port ''. [2017-02-01 18:36:43] DEBUG[5616] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2017-02-01 18:36:43] DEBUG[5616] acl.c: For destination '212.96.122.148', our source address is '195.19.212.8'. [2017-02-01 18:36:43] DEBUG[5616] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3658069fd0' [2017-02-01 18:36:43] DEBUG[5616] netsock2.c: Splitting '212.96.122.148' into... [2017-02-01 18:36:43] DEBUG[5616] netsock2.c: ...host '212.96.122.148' and port ''. [2017-02-01 18:36:43] DEBUG[15332][C-000002e5] res_srtp.c: Adding new policy for SSRC 1683349192 [2017-02-01 18:36:43] DEBUG[15332][C-000002e5] res_srtp.c: Adding new policy for SSRC 1683349192 [2017-02-01 18:36:43] DEBUG[15332][C-000002e5] res_rtp_asterisk.c: 0x7f36580ec170 -- Probation learning mode pass with source address 212.96.122.148:53278 [2017-02-01 18:36:43] DEBUG[15334][C-000002e5] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2017-02-01 18:36:43] DEBUG[15332][C-000002e5] res_rtp_asterisk.c: Got RTCP report of 80 bytes [2017-02-01 18:36:43] DEBUG[5833] netsock2.c: Splitting '212.96.122.148:53279' into... [2017-02-01 18:36:43] DEBUG[5833] netsock2.c: ...host '212.96.122.148' and port '53279'. [2017-02-01 18:36:43] DEBUG[5833] netsock2.c: Splitting '195.19.212.8:13861' into... [2017-02-01 18:36:43] DEBUG[5833] netsock2.c: ...host '195.19.212.8' and port '13861'. [2017-02-01 18:36:45] DEBUG[15332][C-000002e5] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2017-02-01 18:36:45] DEBUG[5833] netsock2.c: Splitting '212.96.122.148:53279' into... [2017-02-01 18:36:45] DEBUG[5833] netsock2.c: ...host '212.96.122.148' and port '53279'. [2017-02-01 18:36:45] DEBUG[5833] netsock2.c: Splitting '195.19.212.8:13861' into... [2017-02-01 18:36:45] DEBUG[5833] netsock2.c: ...host '195.19.212.8' and port '13861'. [2017-02-01 18:36:46] DEBUG[15335] http.c: HTTP opening session. Top level [2017-02-01 18:36:46] DEBUG[15335] http.c: HTTP Request URI is /ari/endpoints/PJSIP/598 [2017-02-01 18:36:46] DEBUG[15335] http.c: match request [ari/endpoints/PJSIP/598] with handler [httpstatus] len 10 [2017-02-01 18:36:46] DEBUG[15335] http.c: match request [ari/endpoints/PJSIP/598] with handler [static] len 6 [2017-02-01 18:36:46] DEBUG[15335] http.c: match request [ari/endpoints/PJSIP/598] with handler [ari] len 3 [2017-02-01 18:36:46] DEBUG[15335] http.c: Match made with [ari] [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Finding handler for endpoints [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking playbacks [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking events [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking sounds [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking channels [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking applications [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking asterisk [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking deviceStates [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking recordings [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking endpoints [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Got it! [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Finding handler for PJSIP [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking sendMessage [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking tech [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Got it! [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Finding handler for 598 [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Checking resource [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Got it! [2017-02-01 18:36:46] DEBUG[15335] res_ari.c: Examining ARI response: 200 OK Content-type: application/json { "technology": "PJSIP", "resource": "598", "state": "online", "channel_ids": [ "1485963401.3198" ] } [2017-02-01 18:36:46] DEBUG[15335] http.c: HTTP keeping session open. status_code:200 [2017-02-01 18:36:46] DEBUG[15335] http.c: HTTP idle timeout or peer closed connection. [2017-02-01 18:36:46] DEBUG[15335] http.c: HTTP closing session. Top level [2017-02-01 18:36:47] DEBUG[5648] res_pjsip_registrar_expire.c: Woke up at 1485963407 Interval: 30 [2017-02-01 18:36:47] DEBUG[5648] res_pjsip_registrar_expire.c: Expiring 0 contacts [2017-02-01 18:36:47] DEBUG[15334][C-000002e5] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '192.168.5.2:10021' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '192.168.5.2' and port '10021'. [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '192.168.5.4:14057' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '192.168.5.4' and port '14057'. [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '192.168.5.4:14057' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '192.168.5.4' and port '14057'. [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '192.168.5.2:10021' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '192.168.5.2' and port '10021'. [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '195.19.212.8:13861' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '195.19.212.8' and port '13861'. [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: Splitting '212.96.122.148:53279' into... [2017-02-01 18:36:47] DEBUG[5833] netsock2.c: ...host '212.96.122.148' and port '53279'. [2017-02-01 18:36:48] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (689 bytes) from WS:192.168.10.63:37348 ---> BYE sip:192.168.10.63:37348;transport=WS SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKSUvJtceuDhlKuIFElBIWncUq3sHoHzy5;rport From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=ca7d8bc4-fdbd-4b0f-983d-754e7759f698 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 CSeq: 22822 BYE Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="598",realm="asterisk",nonce="1485963401/4f19458daa2669bd25b08c9f9a992d8e",uri="sip:192.168.10.63:37348;transport=WS",response="5cbe77493748418400fcfce28a54aad2",algorithm=md5,cnonce="7c65564b9fcfec3d29f3c99ceab5c2f2",opaque="09fc85e96a898deb",qop=auth,nc=00000003 Organization: TFOMS SK [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:48] DEBUG[15211] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36c00e0288 for Request msg BYE/cseq=22822 (rdata0x7f36580b8d88) [2017-02-01 18:36:48] DEBUG[15211] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000089 on dialog dlg0x7f36c00e0288 [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:48] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:48] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (363 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 200 OK Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKSUvJtceuDhlKuIFElBIWncUq3sHoHzy5 Call-ID: 61b52e94-46ca-1987-a47c-40573497d385 From: ;tag=cFhkIcv84vfgtZARPgh8 To: ;tag=ca7d8bc4-fdbd-4b0f-983d-754e7759f698 CSeq: 22822 BYE Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:48] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 363 [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The current transaction state is Completed [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The current inv state is CONFIRMED [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Source of transaction state change is RX_MSG [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Received request [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Method is BYE [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The state change pertains to the endpoint '598(PJSIP/598-00000599)' [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The current transaction state is Completed [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The transaction state change event is RX_MSG [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge_channel.c: Setting 0x7f36b8019430(PJSIP/598-00000599) state from:0 to:1 [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: pulling 0x7f36b8019430(PJSIP/598-00000599) [2017-02-01 18:36:48] VERBOSE[15332][C-000002e5] bridge_channel.c: Channel PJSIP/598-00000599 left 'simple_bridge' basic-bridge [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019430(PJSIP/598-00000599) is leaving simple_bridge technology [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: dissolving bridge with cause 16(Normal Clearing) [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge_channel.c: Setting 0x7f36b8019290(PJSIP/mypbx-0000059a) state from:0 to:2 [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: queueing action type:13 sub:1001 [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c is dissolved, not performing smart bridge operation. [2017-02-01 18:36:48] DEBUG[15334][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: pulling 0x7f36b8019290(PJSIP/mypbx-0000059a) [2017-02-01 18:36:48] VERBOSE[15334][C-000002e5] bridge_channel.c: Channel PJSIP/mypbx-0000059a left 'simple_bridge' basic-bridge [2017-02-01 18:36:48] DEBUG[15334][C-000002e5] bridge_channel.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: 0x7f36b8019290(PJSIP/mypbx-0000059a) is leaving simple_bridge technology [2017-02-01 18:36:48] DEBUG[15334][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c is dissolved, not performing smart bridge operation. [2017-02-01 18:36:48] DEBUG[15334][C-000002e5] channel.c: Hanging up channel 'PJSIP/mypbx-0000059a' [2017-02-01 18:36:48] DEBUG[15334][C-000002e5] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [2017-02-01 18:36:48] DEBUG[3707] cdr.c: Finalized CDR for PJSIP/598-00000599 - start 1485963401.619749 answer 1485963402.850543 end 1485963408.025614 dispo ANSWERED [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: actually destroying basic bridge, nobody wants it anymore [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: calling basic bridge destructor [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: calling simple_bridge technology stop [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] bridge.c: Bridge a46083d6-1224-449b-a3cc-265771cf0f0c: calling simple_bridge technology destructor [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('BRIDGE_EXIT',{ts '2017-02-01 18:36:48.25552'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','Dial','PJSIP/135@mypbx,60',3,'','1485963401.3198','1485963401.3198','PJSIP/mypbx-0000059a','','')] [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] pbx.c: Spawn extension (from-internal,135,2) exited non-zero on 'PJSIP/598-00000599' [2017-02-01 18:36:48] VERBOSE[15332][C-000002e5] pbx.c: Spawn extension (from-internal, 135, 2) exited non-zero on 'PJSIP/598-00000599' [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/598-00000599' [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] channel.c: Hanging up channel 'PJSIP/598-00000599' [2017-02-01 18:36:48] DEBUG[15332][C-000002e5] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Method is BYE [2017-02-01 18:36:48] DEBUG[15326] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:48] DEBUG[15326] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:48] DEBUG[15326] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:48] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - 598 [2017-02-01 18:36:48] DEBUG[15326] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:48] VERBOSE[15326] res_pjsip_logger.c: <--- Transmitting SIP request (394 bytes) to UDP:192.168.5.2:5060 ---> BYE sip:135@192.168.5.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.5.4:5060;rport;branch=z9hG4bKPj23d819a4-81b2-4b57-9301-fb31c6cc98c1 From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: ;tag=as282f9a87 Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26196 BYE Reason: Q.850;cause=16 Max-Forwards: 70 User-Agent: TFOMSSK Content-Length: 0 [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx(PJSIP/mypbx-0000059a)' [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The current transaction state is Calling [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The transaction state change event is TX_MSG [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The current inv state is CONFIRMED [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:48] DEBUG[3340] devicestate.c: Changing state for PJSIP/598 - state 1 (Not in use) [2017-02-01 18:36:48] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - mypbx [2017-02-01 18:36:48] DEBUG[3340] db.c: Unable to find key 'mypbx' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:48] DEBUG[3340] res_sorcery_astdb.c: Failed to retrieve object 'mypbx' from astdb [2017-02-01 18:36:48] DEBUG[3340] devicestate.c: Changing state for PJSIP/mypbx - state 1 (Not in use) [2017-02-01 18:36:48] DEBUG[5857] app_queue.c: Device 'PJSIP/598' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2017-02-01 18:36:48] DEBUG[5857] app_queue.c: Device 'PJSIP/mypbx' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2017-02-01 18:36:48] VERBOSE[5345] res_pjsip_logger.c: <--- Received SIP response (456 bytes) from UDP:192.168.5.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.5.4:5060;branch=z9hG4bKPj23d819a4-81b2-4b57-9301-fb31c6cc98c1;received=192.168.5.4;rport=5060 From: "598" ;tag=cd011762-f4a1-49ba-9090-f0064d95adab To: ;tag=as282f9a87 Call-ID: 1d30af9a-0b03-42e1-818e-01d17b6ddec3 CSeq: 26196 BYE Server: TFOMS Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 [2017-02-01 18:36:48] DEBUG[5345] netsock2.c: Splitting '192.168.5.2:5060' into... [2017-02-01 18:36:48] DEBUG[5345] netsock2.c: ...host '192.168.5.2' and port '5060'. [2017-02-01 18:36:48] DEBUG[5345] netsock2.c: Splitting '192.168.5.4:5060' into... [2017-02-01 18:36:48] DEBUG[5345] netsock2.c: ...host '192.168.5.4' and port '5060'. [2017-02-01 18:36:48] DEBUG[5345] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f36b40c2a88 for Response msg 200/BYE/cseq=26196 (rdata0x7f36a0001dd8) [2017-02-01 18:36:48] DEBUG[5345] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/mypbx-000006e8 on dialog dlg0x7f36b40c2a88 [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The state change pertains to the endpoint '598()' [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f36c00f5098 [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The current transaction state is Terminated [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The transaction state change event is TIMER [2017-02-01 18:36:48] DEBUG[5345] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:48] DEBUG[15211] res_pjsip_session.c: Destroying SIP session with endpoint 598 [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx()' [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: There is no transaction involved in this state change [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Source of transaction state change is RX_MSG [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Received response [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Response is 200 OK [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:48] DEBUG[15211] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3658069fd0' [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx()' [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The current transaction state is Completed [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The transaction state change event is RX_MSG [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Received response [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: Response is 200 OK [2017-02-01 18:36:48] DEBUG[15326] res_pjsip_session.c: BYE received final response code 200 [2017-02-01 18:36:48] DEBUG[15211] rtp_engine.c: Destroyed RTP instance '0x7f3658069fd0' [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3707] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3707] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES ({ ts '2017-02-01 18:36:41' },'"598" <598>','598','135','from-internal','PJSIP/598-00000599','PJSIP/mypbx-0000059a','Dial','PJSIP/135@mypbx,60',6,5,'ANSWERED',3,'1485963401.3198')] [2017-02-01 18:36:48] DEBUG[3707] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3707] 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 ('"598" <598>','598','135','from-internal','PJSIP/598-00000599','PJSIP/mypbx-0000059a','Dial','PJSIP/135@mypbx,60','2017-02-01 18:36:41','2017-02-01 18:36:42','2017-02-01 18:36:48','6','5','ANSWERED','DOCUMENTATION','1485963401.3198') [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('BRIDGE_EXIT',{ts '2017-02-01 18:36:48.37163'},'','135','','','','','mypbx-context','PJSIP/mypbx-0000059a','AppDial','(Outgoing Line)',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('HANGUP',{ts '2017-02-01 18:36:48.60095'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','','',3,'','1485963401.3198','1485963401.3198','','','')] [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('CHAN_END',{ts '2017-02-01 18:36:48.76435'},'598','598','598','','','135','from-internal','PJSIP/598-00000599','','',3,'','1485963401.3198','1485963401.3198','','','')] [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('HANGUP',{ts '2017-02-01 18:36:48.94308'},'','135','','','','','mypbx-context','PJSIP/mypbx-0000059a','AppDial','(Outgoing Line)',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:48] DEBUG[3707] cdr.c: CDR for PJSIP/mypbx-0000059a is dialed and has no Party B; discarding [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Reusing ODBC handle 0x7f367c001690 from class 'asteriskcdrdb' [2017-02-01 18:36:48] DEBUG[3723] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,userfield) VALUES ('CHAN_END',{ts '2017-02-01 18:36:48.111530'},'','135','','','','','mypbx-context','PJSIP/mypbx-0000059a','AppDial','(Outgoing Line)',3,'','1485963401.3199','1485963401.3198','','','')] [2017-02-01 18:36:48] DEBUG[3723] res_odbc.c: Releasing ODBC handle 0x7f367c001690 into pool [2017-02-01 18:36:52] DEBUG[5833] netsock2.c: Splitting '192.168.5.4:14057' into... [2017-02-01 18:36:52] DEBUG[5833] netsock2.c: ...host '192.168.5.4' and port '14057'. [2017-02-01 18:36:52] DEBUG[5833] netsock2.c: Splitting '192.168.5.2:10021' into... [2017-02-01 18:36:52] DEBUG[5833] netsock2.c: ...host '192.168.5.2' and port '10021'. [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The state change pertains to the endpoint 'mypbx()' [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x7f365c009a38 [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The current transaction state is Terminated [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The transaction state change event is TIMER [2017-02-01 18:36:53] DEBUG[5345] res_pjsip_session.c: The current inv state is DISCONNCTD [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_session.c: Destroying SIP session with endpoint mypbx [2017-02-01 18:36:53] DEBUG[15211] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f3658025570' [2017-02-01 18:36:53] DEBUG[15211] rtp_engine.c: Destroyed RTP instance '0x7f3658025570' [2017-02-01 18:36:53] VERBOSE[15211] res_pjsip_logger.c: <--- Received SIP request (764 bytes) from WS:192.168.10.63:37348 ---> REGISTER sip:192.168.1.47 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKlUrTCIJIGT22tR13v4oLDhCT1IoL2vZk;rport From: ;tag=NuNLD4METD4Hm1wTlrQm To: Contact: "undefined";expires=0;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 CSeq: 38554 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="598",realm="asterisk",nonce="1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe",uri="sip:192.168.1.47",response="43edccbda20c36af02b9bed344cee1de",algorithm=md5,cnonce="961cc589dab3632cef8f8aae44b50074",opaque="488d6cd36abe5416",qop=auth,nc=00000002 Organization: TFOMS SK [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_transport_websocket.c: Re-wrote Contact URI host/port to 192.168.10.63:37348 [2017-02-01 18:36:53] DEBUG[15211] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=38554 (rdata0x7f36580b8d88) [2017-02-01 18:36:53] DEBUG[15211] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000007d to use for Request msg REGISTER/cseq=38554 (rdata0x7f36580b8d88) [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'mypbx-identify' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748951-identify' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748950-identify' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'rt-identify' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.10.63:37348 does not match identify 'sip_748952-identify' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_ip.c: '192.168.10.63:37348' did not match any identify section rules [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '598' domain '192.168.1.47' [2017-02-01 18:36:53] DEBUG[15211] db.c: Unable to find key '598@192.168.1.47' in family 'ps_endpoints/endpoint' [2017-02-01 18:36:53] DEBUG[15211] res_sorcery_astdb.c: Failed to retrieve object '598@192.168.1.47' from astdb [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_endpoint_identifier_user.c: Identified by From username '598' domain '192.168.1.47' [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_authenticator_digest.c: Calculated nonce 1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe. Actual nonce is 1485963397/ff4ebb1b9a2e87daadf2db21cdcdc7fe [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port ''. [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_registrar.c: Matched id '598' to aor '598' [2017-02-01 18:36:53] DEBUG[15211] res_pjsip_registrar.c: Matched aor '598' by To username [2017-02-01 18:36:53] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:53] DEBUG[15211] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] VERBOSE[15211] res_pjsip_registrar.c: Removed contact 'sip:598@192.168.10.63:37348;transport=ws;rtcweb-breaker=yes' from AOR '598' due to request [2017-02-01 18:36:53] VERBOSE[15216] res_pjsip/pjsip_configuration.c: Contact 598/sip:598@192.168.10.63:37348;transport=ws;rtcweb-breaker=yes has been deleted [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:53] DEBUG[15216] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: Splitting '192.168.10.63:37348' into... [2017-02-01 18:36:53] DEBUG[15211] netsock2.c: ...host '192.168.10.63' and port '37348'. [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:53] VERBOSE[15211] res_pjsip_logger.c: <--- Transmitting SIP response (408 bytes) to WS:192.168.10.63:37348 ---> SIP/2.0 200 OK Via: SIP/2.0/WS df7jal23ls0d.invalid;rport=37348;received=192.168.10.63;branch=z9hG4bKlUrTCIJIGT22tR13v4oLDhCT1IoL2vZk Call-ID: cc08cbe0-4b13-2bc9-e16d-11dbbfceda70 From: ;tag=NuNLD4METD4Hm1wTlrQm To: ;tag=z9hG4bKlUrTCIJIGT22tR13v4oLDhCT1IoL2vZk CSeq: 38554 REGISTER Date: Wed, 01 Feb 2017 15:36:53 GMT Server: TFOMSSK Content-Length: 0 [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [2017-02-01 18:36:53] DEBUG[15211] res_http_websocket.c: Writing websocket text frame, length 408 [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [0] in [0, 86400] gives [0](0) [2017-02-01 18:36:53] DEBUG[15216] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [2017-02-01 18:36:53] VERBOSE[15216] res_pjsip/pjsip_configuration.c: Endpoint 598 is now Unreachable [2017-02-01 18:36:53] DEBUG[3340] devicestate.c: No provider found, checking channel drivers for PJSIP - 598 [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2017-02-01 18:36:53] DEBUG[3340] devicestate.c: Changing state for PJSIP/598 - state 5 (Unavailable) [2017-02-01 18:36:53] DEBUG[5857] app_queue.c: Device 'PJSIP/598' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2017-02-01 18:36:53] VERBOSE[5345] res_http_websocket.c: WebSocket connection from '192.168.10.63:37348' closed