[May 21 12:34:16] Asterisk 13.3.2 built by root @ ubuntu on a x86_64 running Linux on 2015-05-18 06:52:16 UTC [May 21 12:34:17] DEBUG[31911] threadpool.c: Worker thread idle timeout reached. Dying. [May 21 12:34:17] DEBUG[31910] threadpool.c: Worker thread idle timeout reached. Dying. [May 21 12:34:17] DEBUG[31906] threadpool.c: Destroying worker thread 9 [May 21 12:34:17] DEBUG[31906] threadpool.c: Destroying worker thread 8 [May 21 12:34:18] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=25606 (rdata0x7fc69000d398) [May 21 12:34:18] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (1099 bytes) from UDP:192.168.1.2:58557 ---> INVITE sip:72@192.168.1.127 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:58557;rport;branch=z9hG4bKPjUlhXLS5SoAyde.2d7KnEhrV6rZdDqZ9c Max-Forwards: 70 From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: Contact: "71" Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ CSeq: 25606 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Telephone 1.1.4 Content-Type: application/sdp Content-Length: 479 v=0 o=- 3641189659 3641189659 IN IP4 192.168.1.2 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4188 RTP/AVP 103 102 104 109 3 0 8 9 101 c=IN IP4 192.168.1.2 b=TIAS:64000 a=rtcp:4189 IN IP4 192.168.1.2 a=sendrecv a=rtpmap:103 speex/16000 a=rtpmap:102 speex/8000 a=rtpmap:104 speex/32000 a=rtpmap:109 iLBC/8000 a=fmtp:109 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=25606 (rdata0x7fc690019f18) [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '71@192.168.1.127' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 71 [May 21 12:34:18] DEBUG[31907] pjsip: endpoint .Response msg 401/INVITE/cseq=25606 (tdta0x7fc6900176f0) created [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_auths WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [32] in [-2147483648, 2147483647] gives [32](0) [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: ChallengeSent Privilege: security,all EventTV: 2015-05-21T12:34:18.580+0300 Severity: Informational Service: PJSIP EventVersion: 1 AccountID: 71 SessionID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ LocalAddress: IPV4/UDP/192.168.1.127/5060 RemoteAddress: IPV4/UDP/192.168.1.2/58557 Challenge: [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (542 bytes) to UDP:192.168.1.2:58557 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.2:58557;rport=58557;received=192.168.1.2;branch=z9hG4bKPjUlhXLS5SoAyde.2d7KnEhrV6rZdDqZ9c Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=z9hG4bKPjUlhXLS5SoAyde.2d7KnEhrV6rZdDqZ9c CSeq: 25606 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1432200858/375562696564feddf779c3abb5c39581",opaque="4593505e7554ac97",algorithm=md5,qop="auth" Server: PBXe 1.4.0 Content-Length: 0 [May 21 12:34:18] DEBUG[31907] pjsip: tdta0x7fc69001 .Destroying txdata Response msg 401/INVITE/cseq=25606 (tdta0x7fc6900176f0) [May 21 12:34:18] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=25606 (rdata0x7fc69000d398) [May 21 12:34:18] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (371 bytes) from UDP:192.168.1.2:58557 ---> ACK sip:72@192.168.1.127 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:58557;rport;branch=z9hG4bKPjUlhXLS5SoAyde.2d7KnEhrV6rZdDqZ9c Max-Forwards: 70 From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=z9hG4bKPjUlhXLS5SoAyde.2d7KnEhrV6rZdDqZ9c Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ CSeq: 25606 ACK Content-Length: 0 [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=25607 (rdata0x7fc69000d398) [May 21 12:34:18] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (1388 bytes) from UDP:192.168.1.2:58557 ---> INVITE sip:72@192.168.1.127 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:58557;rport;branch=z9hG4bKPjY0EcPU4Qt8kQcT9IwZ7g8S38wW9Ovrm8 Max-Forwards: 70 From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: Contact: "71" Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ CSeq: 25607 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Telephone 1.1.4 Authorization: Digest username="71", realm="asterisk", nonce="1432200858/375562696564feddf779c3abb5c39581", uri="sip:72@192.168.1.127", response="9ecc85109dfd8b225d64e394406c4661", algorithm=md5, cnonce="CbrSYsHo7avCuBjok.Q6thBQnWPXLiM0", opaque="4593505e7554ac97", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 479 v=0 o=- 3641189659 3641189659 IN IP4 192.168.1.2 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4188 RTP/AVP 103 102 104 109 3 0 8 9 101 c=IN IP4 192.168.1.2 b=TIAS:64000 a=rtcp:4189 IN IP4 192.168.1.2 a=sendrecv a=rtpmap:103 speex/16000 a=rtpmap:102 speex/8000 a=rtpmap:104 speex/32000 a=rtpmap:109 iLBC/8000 a=fmtp:109 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31908] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=25606 (rdata0x7fc69001f0e8) [May 21 12:34:18] DEBUG[31909] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=25607 (rdata0x7fc690021038) [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [May 21 12:34:18] DEBUG[31908] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31908] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Parameter 1 ('id') = '71@192.168.1.127' [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [May 21 12:34:18] DEBUG[31909] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31909] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Parameter 1 ('id') = '71@192.168.1.127' [May 21 12:34:18] DEBUG[31909] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31909] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31908] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31908] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31908] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31909] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31909] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31908] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31908] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31908] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 71 [May 21 12:34:18] DEBUG[31909] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 71 [May 21 12:34:18] DEBUG[31909] pjsip: endpoint .Response msg 401/INVITE/cseq=25607 (tdta0x7fc69001e0b0) created [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_auths WHERE id = ? [May 21 12:34:18] DEBUG[31909] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31909] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31909] config.c: extract int from [32] in [-2147483648, 2147483647] gives [32](0) [May 21 12:34:18] DEBUG[31909] res_pjsip_authenticator_digest.c: Calculated nonce 1432200858/375562696564feddf779c3abb5c39581. Actual nonce is 1432200858/375562696564feddf779c3abb5c39581 [May 21 12:34:18] DEBUG[31909] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31909] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31909] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31909] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: SuccessfulAuth Privilege: security,all EventTV: 2015-05-21T12:34:18.593+0300 Severity: Informational Service: PJSIP EventVersion: 1 AccountID: 71 SessionID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ LocalAddress: IPV4/UDP/192.168.1.127/5060 RemoteAddress: IPV4/UDP/192.168.1.2/58557 UsingPassword: 1 [May 21 12:34:18] DEBUG[31909] pjsip: tdta0x7fc69001 .Destroying txdata Response msg 401/INVITE/cseq=25607 (tdta0x7fc69001e0b0) [May 21 12:34:18] DEBUG[31909] pjsip: tsx0x7fc678012 ..Transaction created for Request msg INVITE/cseq=25607 (rdata0x7fc690021038) [May 21 12:34:18] DEBUG[31909] pjsip: tsx0x7fc678012 .Incoming Request msg INVITE/cseq=25607 (rdata0x7fc690021038) in state Null [May 21 12:34:18] DEBUG[31909] pjsip: tsx0x7fc678012 ..State changed from Null to Trying, event=RX_MSG [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e ...Transaction tsx0x7fc678012728 state changed to Trying [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e .UAS dialog created [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e .Module mod-invite added as dialog usage, data=0x7fc67001f838 [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e ..Session count inc to 2 by mod-invite [May 21 12:34:18] DEBUG[31909] pjsip: inv0x7fc67801e .UAS invite session created for dialog dlg0x7fc67801e868 [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e .Module Session Module added as dialog usage, data=(nil) [May 21 12:34:18] DEBUG[31909] pjsip: dlg0x7fc67801e ..Session count inc to 2 by Session Module [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc678033028' [May 21 12:34:18] DEBUG[31907] res_rtp_asterisk.c: Allocated port 18892 for RTP instance '0x7fc678033028' [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 ICE session created, comp_cnt=2, role is Unknown agent [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a8017f, addr=192.168.1.127:18892, base=192.168.1.127:18892, prio=0x7effffff (2130706431) [May 21 12:34:18] DEBUG[31907] rtp_engine.c: RTP instance '0x7fc678033028' is setup and ready to go [May 21 12:34:18] DEBUG[31907] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc678033028' [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Candidate 1 added: comp_id=2, type=host, foundation=Hc0a8017f, addr=192.168.1.127:18893, base=192.168.1.127:18893, prio=0x7efffffe (2130706430) [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Destroying ICE session 0x7fc67804b5c8 [May 21 12:34:18] DEBUG[31907] pjsip: stuse0x7fc6780 STUN session 0x7fc678030078 destroy request, ref_cnt=4 [May 21 12:34:18] DEBUG[31907] pjsip: stuse0x7fc6780 STUN session 0x7fc678012fd8 destroy request, ref_cnt=3 [May 21 12:34:18] DEBUG[31907] pjsip: ice_session.c ICE session 0x7fc67804b5c8 destroyed [May 21 12:34:18] DEBUG[31907] pjsip: stun_session.c STUN session 0x7fc678030078 destroyed [May 21 12:34:18] DEBUG[31907] pjsip: stun_session.c STUN session 0x7fc678012fd8 destroyed [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 103 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 102 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 104 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 109 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 3 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 0 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 8 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 9 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Setting payload 101 (0x7fc67802fbc8) based on m type on 0x7fc674135490 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 0 (0x7fc678040c18) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 3 (0x7fc678013f68) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 8 (0x7fc678040c98) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 9 (0x7fc678026168) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 101 (0x7fc678040d18) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 102 (0x7fc67800cb38) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 103 (0x7fc678050798) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 104 (0x7fc67800cbb8) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Copying payload 109 (0x7fc67800cc38) from 0x7fc674135490 to 0x7fc6780331f0 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Media stream 'audio' handled by audio [May 21 12:34:18] DEBUG[31907] pjsip: endpoint .Response msg 100/INVITE/cseq=25607 (tdta0x7fc67803da50) created [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e .Initial answer Response msg 100/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [May 21 12:34:18] DEBUG[31907] pjsip: inv0x7fc67801e .Sending Response msg 100/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e ..Sending Response msg 100/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc678012 ..Sending Response msg 100/INVITE/cseq=25607 (tdta0x7fc67803da50) in state Trying [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (343 bytes) to UDP:192.168.1.2:58557 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.2:58557;rport=58557;received=192.168.1.2;branch=z9hG4bKPjY0EcPU4Qt8kQcT9IwZ7g8S38wW9Ovrm8 Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: CSeq: 25607 INVITE Server: PBXe 1.4.0 Content-Length: 0 [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc678012 ...State changed from Trying to Proceeding, event=TX_MSG [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e ....Transaction tsx0x7fc678012728 state changed to Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71()' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is INCOMING [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71()' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current transaction state is Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is INCOMING [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e Module NAT added as dialog usage, data=(nil) [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/71-00000004 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 71 CallerIDName: 71 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1432200858.8 [May 21 12:34:18] DEBUG[31907] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/71-00000004 [May 21 12:34:18] DEBUG[32180][C-00000002] pbx.c: Launching 'Stasis' [May 21 12:34:18] VERBOSE[32180][C-00000002] pbx.c: Executing [72@node:1] Stasis("PJSIP/71-00000004", "pbxe") in new stack [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/71-00000004 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 71 CallerIDName: 71 ConnectedLineNum: ConnectedLineName: Language: ru AccountCode: Context: node Exten: 72 Priority: 1 Uniqueid: 1432200858.8 Extension: 72 Application: Stasis AppData: pbxe [May 21 12:34:18] DEBUG[32180][C-00000002] stasis/app.c: Channel '1432200858.8' is 1 interested in pbxe [May 21 12:34:18] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "StasisStart", "timestamp": "2015-05-21T12:34:18.607+0300", "args": [], "channel": { "id": "1432200858.8", "name": "PJSIP/71-00000004", "state": "Ring", "caller": { "name": "71", "number": "71" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "node", "exten": "72", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.602+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:18] DEBUG[32181] http.c: HTTP opening session. Top level [May 21 12:34:18] DEBUG[32181] http.c: HTTP Request URI is /ari/channels?endpoint=PJSIP%2F502&&&&&app=pbxe&appArgs=O&&&channelId=333dc9d9-a3de-4fcc-a023-5c04f7ffac3f&&originator=1432200858.8 [May 21 12:34:18] DEBUG[32181] http.c: match request [ari/channels] with handler [httpstatus] len 10 [May 21 12:34:18] DEBUG[32181] http.c: match request [ari/channels] with handler [phoneprov] len 9 [May 21 12:34:18] DEBUG[32181] http.c: match request [ari/channels] with handler [static] len 6 [May 21 12:34:18] DEBUG[32181] http.c: match request [ari/channels] with handler [ari] len 3 [May 21 12:34:18] DEBUG[32181] http.c: Match made with [ari] [May 21 12:34:18] DEBUG[32181] res_ari.c: Finding handler for channels [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking endpoints [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking recordings [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking asterisk [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking sounds [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking playbacks [May 21 12:34:18] DEBUG[32181] res_ari.c: Checking channels [May 21 12:34:18] DEBUG[32181] res_ari.c: Got it! [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_aors WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_contacts WHERE id LIKE ? ORDER BY id [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id LIKE') = '502;@%' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [0, 86400] gives [0](0) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 UAC dialog created [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module Outbound Authentica added as dialog usage, data=0x7fc6780424e0 [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module mod-invite added as dialog usage, data=0x7fc678042608 [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 .Session count inc to 2 by mod-invite [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module mod-100rel added as dialog usage, data=0x7fc6780427c8 [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 100rel module attached [May 21 12:34:18] DEBUG[31907] pjsip: inv0x7fc678041 UAC invite session created for dialog dlg0x7fc678041a58 [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 .Session count inc to 2 by Session Module [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module Session Module added as dialog usage, data=(nil) [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f Extension: s Application: AppDial2 AppData: (Outgoing Line) [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f [May 21 12:34:18] DEBUG[32181] res_stasis.c: pbxe: Subscribing to 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f [May 21 12:34:18] DEBUG[32181] stasis/app.c: Channel '333dc9d9-a3de-4fcc-a023-5c04f7ffac3f' is 1 interested in pbxe [May 21 12:34:18] DEBUG[32181] res_ari.c: Examining ARI response: 200 OK Content-type: application/json { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Down", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" } [May 21 12:34:18] DEBUG[32181] http.c: HTTP closing session. status_code:200 [May 21 12:34:18] DEBUG[32183] http.c: HTTP opening session. Top level [May 21 12:34:18] DEBUG[32183] http.c: HTTP Request URI is /ari/channels/1432200858.8/ring [May 21 12:34:18] DEBUG[32183] http.c: match request [ari/channels/1432200858.8/ring] with handler [httpstatus] len 10 [May 21 12:34:18] DEBUG[32183] http.c: match request [ari/channels/1432200858.8/ring] with handler [phoneprov] len 9 [May 21 12:34:18] DEBUG[32183] http.c: match request [ari/channels/1432200858.8/ring] with handler [static] len 6 [May 21 12:34:18] DEBUG[32183] http.c: match request [ari/channels/1432200858.8/ring] with handler [ari] len 3 [May 21 12:34:18] DEBUG[32183] http.c: Match made with [ari] [May 21 12:34:18] DEBUG[32183] res_ari.c: Finding handler for channels [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking endpoints [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking recordings [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking asterisk [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking sounds [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking playbacks [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking channels [May 21 12:34:18] DEBUG[32183] res_ari.c: Got it! [May 21 12:34:18] DEBUG[32183] res_ari.c: Finding handler for 1432200858.8 [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking channelId [May 21 12:34:18] DEBUG[32183] res_ari.c: Got it! [May 21 12:34:18] DEBUG[32183] res_ari.c: Finding handler for ring [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking continue [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking redirect [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking answer [May 21 12:34:18] DEBUG[32183] res_ari.c: Checking ring [May 21 12:34:18] DEBUG[32183] res_ari.c: Got it! [May 21 12:34:18] DEBUG[32183] res_ari.c: Examining ARI response: 204 No Content [May 21 12:34:18] DEBUG[32183] http.c: HTTP closing session. status_code:204 [May 21 12:34:18] DEBUG[31907] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fc67801f438' [May 21 12:34:18] DEBUG[31907] res_rtp_asterisk.c: Allocated port 11654 for RTP instance '0x7fc67801f438' [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 ICE session created, comp_cnt=2, role is Unknown agent [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a8017f, addr=192.168.1.127:11654, base=192.168.1.127:11654, prio=0x7effffff (2130706431) [May 21 12:34:18] DEBUG[31907] rtp_engine.c: RTP instance '0x7fc67801f438' is setup and ready to go [May 21 12:34:18] DEBUG[31907] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fc67801f438' [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port ''. [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Candidate 1 added: comp_id=2, type=host, foundation=Hc0a8017f, addr=192.168.1.127:11655, base=192.168.1.127:11655, prio=0x7efffffe (2130706430) [May 21 12:34:18] DEBUG[31907] pjsip: icess0x7fc6780 Destroying ICE session 0x7fc67802d038 [May 21 12:34:18] DEBUG[31907] pjsip: stuse0x7fc6780 STUN session 0x7fc678020578 destroy request, ref_cnt=4 [May 21 12:34:18] DEBUG[31907] pjsip: stuse0x7fc6780 STUN session 0x7fc678043c58 destroy request, ref_cnt=3 [May 21 12:34:18] DEBUG[31907] pjsip: ice_session.c ICE session 0x7fc67802d038 destroyed [May 21 12:34:18] DEBUG[31907] pjsip: stun_session.c STUN session 0x7fc678020578 destroyed [May 21 12:34:18] DEBUG[31907] pjsip: stun_session.c STUN session 0x7fc678043c58 destroyed [May 21 12:34:18] DEBUG[31907] pjsip: endpoint Request msg INVITE/cseq=15125 (tdta0x7fc69001e0b0) created. [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module NAT added as dialog usage, data=(nil) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 Module WebSocket Transport Module added as dialog usage, data=(nil) [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_aors WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 21 12:34:18] DEBUG[31907] pjsip: inv0x7fc678041 .Sending Request msg INVITE/cseq=15125 (tdta0x7fc69001e0b0) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ..Sending Request msg INVITE/cseq=15125 (tdta0x7fc69001e0b0) [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d ...Transaction created for Request msg INVITE/cseq=15124 (tdta0x7fc69001e0b0) [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: PJSIP/502-00000005 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: 71 DestConnectedLineName: 71 DestLanguage: ru DestAccountCode: DestContext: dialmap DestExten: s DestPriority: 1 DestUniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f DialString: 502 [May 21 12:34:18] VERBOSE[32182] dial.c: Called 502 [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d ..Sending Request msg INVITE/cseq=15124 (tdta0x7fc69001e0b0) in state Null [May 21 12:34:18] DEBUG[31907] pjsip: sip_resolve.c ...Target '192.168.1.50:5060' type=Unspecified resolved to '192.168.1.50:5060' type=UDP (UDP transport) [May 21 12:34:18] DEBUG[31907] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.127:5060 [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.50' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port ''. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:18] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP request (960 bytes) to UDP:192.168.1.50:5060 ---> INVITE sip:502@192.168.1.50:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:5060;rport;branch=z9hG4bKPj745ff52f-4287-42fc-a963-7f7f1bb47883 From: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca To: Contact: Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 15124 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: PBXe 1.4.0 Content-Type: application/sdp Content-Length: 287 v=0 o=- 2027632139 2027632139 IN IP4 192.168.1.127 s=Asterisk c=IN IP4 192.168.1.127 t=0 0 m=audio 11654 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d ...State changed from Null to Calling, event=TX_MSG [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ....Transaction tsx0x7fc67802d0b8 state changed to Calling [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is CALLING [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending request [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_aors WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current transaction state is Calling [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is CALLING [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending request [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_aors WHERE id = ? [May 21 12:34:18] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 21 12:34:18] DEBUG[31907] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 21 12:34:18] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=15124 (rdata0x7fc69000d398) [May 21 12:34:18] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP response (332 bytes) from UDP:192.168.1.50:5060 ---> SIP/2.0 100 Trying To: From: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 15124 INVITE Via: SIP/2.0/UDP 192.168.1.127:5060;branch=z9hG4bKPj745ff52f-4287-42fc-a963-7f7f1bb47883 Server: Cisco/SPA502G-7.4.8a Content-Length: 0 [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=15124 (rdata0x7fc690023e18) [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d .Incoming Response msg 100/INVITE/cseq=15124 (rdata0x7fc690023e18) in state Calling [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d ..State changed from Calling to Proceeding, event=RX_MSG [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ...Received Response msg 100/INVITE/cseq=15124 (rdata0x7fc690023e18) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ...Transaction tsx0x7fc67802d0b8 state changed to Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current transaction state is Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The transaction state change event is RX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is CALLING [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Received response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Response is 100 Trying [May 21 12:34:18] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=15124 (rdata0x7fc69000d398) [May 21 12:34:18] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP response (405 bytes) from UDP:192.168.1.50:5060 ---> SIP/2.0 180 Ringing To: ;tag=e394cd5176fe64a8i0 From: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 15124 INVITE Via: SIP/2.0/UDP 192.168.1.127:5060;branch=z9hG4bKPj745ff52f-4287-42fc-a963-7f7f1bb47883 Contact: "Илья" Server: Cisco/SPA502G-7.4.8a Content-Length: 0 [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:18] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=15124 (rdata0x7fc690023e18) [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d .Incoming Response msg 180/INVITE/cseq=15124 (rdata0x7fc690023e18) in state Proceeding [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc67802d ..State changed from Proceeding to Proceeding, event=RX_MSG [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ...Received Response msg 180/INVITE/cseq=15124 (rdata0x7fc690023e18) [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ....Route-set updated [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc678041 ...Transaction tsx0x7fc67802d0b8 state changed to Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is EARLY [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Received response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Response is 180 Ringing [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current transaction state is Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The transaction state change event is RX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is EARLY [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Received response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Response is 180 Ringing [May 21 12:34:18] VERBOSE[32182] dial.c: PJSIP/502-00000005 is ringing [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f [May 21 12:34:18] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "ChannelStateChange", "timestamp": "2015-05-21T12:34:18.693+0300", "channel": { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Ringing", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:18] DEBUG[31894] devicestate.c: No provider found, checking channel drivers for PJSIP - 502 [May 21 12:34:18] DEBUG[31894] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31894] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:18] DEBUG[31894] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31894] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] devicestate.c: Changing state for PJSIP/502 - state 6 (Ringing) [May 21 12:34:18] DEBUG[31952] app_queue.c: Device 'PJSIP/502' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/502 State: RINGING [May 21 12:34:18] DEBUG[31894] devicestate.c: No provider found, checking channel drivers for PJSIP - 71 [May 21 12:34:18] DEBUG[31894] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:18] DEBUG[31894] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:18] DEBUG[31894] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:18] DEBUG[31894] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:18] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:18] DEBUG[31894] devicestate.c: Changing state for PJSIP/71 - state 2 (In use) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [May 21 12:34:18] DEBUG[31907] pjsip: inv0x7fc67801e .Sending Response msg 180/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:18] DEBUG[31952] app_queue.c: Device 'PJSIP/71' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 21 12:34:18] DEBUG[31971] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/71 State: INUSE [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e ..Sending Response msg 180/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc678012 ..Sending Response msg 180/INVITE/cseq=25607 (tdta0x7fc67803da50) in state Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.127:5060 [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:18] DEBUG[31907] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:18] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:18] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (531 bytes) to UDP:192.168.1.2:58557 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.2:58557;rport=58557;received=192.168.1.2;branch=z9hG4bKPjY0EcPU4Qt8kQcT9IwZ7g8S38wW9Ovrm8 Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=923989f1-4332-4014-bec3-43ded14ee071 CSeq: 25607 INVITE Server: PBXe 1.4.0 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Content-Length: 0 [May 21 12:34:18] DEBUG[31907] pjsip: tsx0x7fc678012 ...State changed from Proceeding to Proceeding, event=TX_MSG [May 21 12:34:18] DEBUG[31907] pjsip: dlg0x7fc67801e ....Transaction tsx0x7fc678012728 state changed to Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is EARLY [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current transaction state is Proceeding [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: The current inv state is EARLY [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:18] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [May 21 12:34:20] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=15124 (rdata0x7fc69000d398) [May 21 12:34:20] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP response (731 bytes) from UDP:192.168.1.50:5060 ---> SIP/2.0 200 OK To: ;tag=e394cd5176fe64a8i0 From: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 15124 INVITE Via: SIP/2.0/UDP 192.168.1.127:5060;branch=z9hG4bKPj745ff52f-4287-42fc-a963-7f7f1bb47883 Contact: "Илья" Server: Cisco/SPA502G-7.4.8a Content-Length: 206 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 296774 296774 IN IP4 192.168.1.50 s=- c=IN IP4 192.168.1.50 t=0 0 m=audio 16492 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=15124 (rdata0x7fc690023658) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d .Incoming Response msg 200/INVITE/cseq=15124 (rdata0x7fc690023658) in state Proceeding [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d ..State changed from Proceeding to Terminated, event=RX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ...Received Response msg 200/INVITE/cseq=15124 (rdata0x7fc690023658) [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ....Route-set updated [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ....Route-set frozen [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ...Transaction tsx0x7fc67802d0b8 state changed to Terminated [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONNECTING [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Received response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Response is 200 OK [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc678041 ....Got SDP answer in Response msg 200/INVITE/cseq=15124 (rdata0x7fc690023658) [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc678041 ....SDP negotiation done, status=0 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.50' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port ''. [May 21 12:34:20] DEBUG[31907] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc67801f438' [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 9 (0x7fc67802f0f8) based on m type on 0x7fc674134c70 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 101 (0x7fc67802f0f8) based on m type on 0x7fc674134c70 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 9 (0x7fc678044b98) from 0x7fc674134c70 to 0x7fc67801f600 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 101 (0x7fc67801b4c8) from 0x7fc674134c70 to 0x7fc67801f600 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc678041 ....Received Response msg 200/INVITE/cseq=15124 (rdata0x7fc690023658), sending ACK [May 21 12:34:20] DEBUG[31907] pjsip: endpoint ....Request msg ACK/cseq=15124 (tdta0x7fc67001c290) created. [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 .....Sending Request msg ACK/cseq=15124 (tdta0x7fc67001c290) [May 21 12:34:20] DEBUG[31907] pjsip: sip_resolve.c .....Target '192.168.1.50:5060' type=Unspecified resolved to '192.168.1.50:5060' type=UDP (UDP transport) [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.50' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port ''. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:20] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP request (390 bytes) to UDP:192.168.1.50:5060 ---> ACK sip:502@192.168.1.50:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:5060;rport;branch=z9hG4bKPj427fb3e8-bd62-4434-8c8e-3fbc489ce1dd From: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca To: ;tag=e394cd5176fe64a8i0 Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 15124 ACK Max-Forwards: 70 User-Agent: PBXe 1.4.0 Content-Length: 0 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc67802d0b8) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Sending request [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is ACK [May 21 12:34:20] DEBUG[31907] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_aors WHERE id = ? [May 21 12:34:20] DEBUG[31907] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:20] DEBUG[31907] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:20] DEBUG[31907] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 21 12:34:20] DEBUG[31907] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 21 12:34:20] DEBUG[31907] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31907] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 21 12:34:20] DEBUG[31907] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Terminated [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Received response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Response is 200 OK [May 21 12:34:20] VERBOSE[32182] dial.c: PJSIP/502-00000005 answered [May 21 12:34:20] VERBOSE[32182] ari/resource_channels.c: Launching Stasis(pbxe,O) on PJSIP/502-00000005 [May 21 12:34:20] DEBUG[32182] stasis/app.c: Channel '333dc9d9-a3de-4fcc-a023-5c04f7ffac3f' is 2 interested in pbxe [May 21 12:34:20] DEBUG[31894] devicestate.c: No provider found, checking channel drivers for PJSIP - 502 [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "ChannelStateChange", "timestamp": "2015-05-21T12:34:20.365+0300", "channel": { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[31894] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:20] DEBUG[31894] res_config_odbc.c: Parameter 1 ('id') = '502' [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: PJSIP/502-00000005 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: 71 DestConnectedLineName: 71 DestLanguage: ru DestAccountCode: DestContext: dialmap DestExten: s DestPriority: 1 DestUniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f DialStatus: ANSWER [May 21 12:34:20] DEBUG[31894] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:20] DEBUG[31894] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] devicestate.c: Changing state for PJSIP/502 - state 2 (In use) [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "StasisStart", "timestamp": "2015-05-21T12:34:20.366+0300", "args": [ "O" ], "channel": { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[31952] app_queue.c: Device 'PJSIP/502' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/502 State: INUSE [May 21 12:34:20] DEBUG[32184] http.c: HTTP opening session. Top level [May 21 12:34:20] DEBUG[32184] http.c: HTTP Request URI is /ari/channels/1432200858.8/answer [May 21 12:34:20] DEBUG[32184] http.c: match request [ari/channels/1432200858.8/answer] with handler [httpstatus] len 10 [May 21 12:34:20] DEBUG[32184] http.c: match request [ari/channels/1432200858.8/answer] with handler [phoneprov] len 9 [May 21 12:34:20] DEBUG[32184] http.c: match request [ari/channels/1432200858.8/answer] with handler [static] len 6 [May 21 12:34:20] DEBUG[32184] http.c: match request [ari/channels/1432200858.8/answer] with handler [ari] len 3 [May 21 12:34:20] DEBUG[32184] http.c: Match made with [ari] [May 21 12:34:20] DEBUG[32184] res_ari.c: Finding handler for channels [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking endpoints [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking recordings [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking asterisk [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking sounds [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking playbacks [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking channels [May 21 12:34:20] DEBUG[32184] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32184] res_ari.c: Finding handler for 1432200858.8 [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking channelId [May 21 12:34:20] DEBUG[32184] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32184] res_ari.c: Finding handler for answer [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking continue [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking redirect [May 21 12:34:20] DEBUG[32184] res_ari.c: Checking answer [May 21 12:34:20] DEBUG[32184] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32184] res_stasis_answer.c: 1432200858.8: Sending answer command [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc67802d Timeout timer event [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc67802d .State changed from Terminated to Destroyed, event=TIMER [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc67802d Transaction destroyed! [May 21 12:34:20] DEBUG[32180][C-00000002] res_stasis_answer.c: 1432200858.8: Answering [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "ChannelStateChange", "timestamp": "2015-05-21T12:34:20.415+0300", "channel": { "id": "1432200858.8", "name": "PJSIP/71-00000004", "state": "Up", "caller": { "name": "71", "number": "71" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "node", "exten": "72", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.602+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[31894] devicestate.c: No provider found, checking channel drivers for PJSIP - 71 [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/71-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 71 CallerIDName: 71 ConnectedLineNum: ConnectedLineName: Language: ru AccountCode: Context: node Exten: 72 Priority: 1 Uniqueid: 1432200858.8 [May 21 12:34:20] DEBUG[31894] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM pbx_endpoints WHERE id = ? [May 21 12:34:20] DEBUG[31894] res_config_odbc.c: Parameter 1 ('id') = '71' [May 21 12:34:20] DEBUG[31894] res_odbc.c: odbc_release_obj2(0x26b7a38) called (obj->txf = (nil)) [May 21 12:34:20] DEBUG[31894] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 21 12:34:20] DEBUG[31894] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 21 12:34:20] DEBUG[31894] devicestate.c: Changing state for PJSIP/71 - state 2 (In use) [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc67801e .SDP negotiation done, status=0 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:20] DEBUG[31907] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc678033028' [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 0 (0x7fc67803aa58) based on m type on 0x7fc674134e70 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 8 (0x7fc67803aa58) based on m type on 0x7fc674134e70 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 101 (0x7fc67803aa58) based on m type on 0x7fc674134e70 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 0 (0x7fc67803aad8) from 0x7fc674134e70 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 8 (0x7fc678038728) from 0x7fc674134e70 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 101 (0x7fc6780387a8) from 0x7fc674134e70 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 200 OK [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc67801e .Sending Response msg 200/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ..Sending Response msg 200/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ..Sending Response msg 200/INVITE/cseq=25607 (tdta0x7fc67803da50) in state Proceeding [May 21 12:34:20] DEBUG[31907] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.127:5060 [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:20] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (924 bytes) to UDP:192.168.1.2:58557 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.2:58557;rport=58557;received=192.168.1.2;branch=z9hG4bKPjY0EcPU4Qt8kQcT9IwZ7g8S38wW9Ovrm8 Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=923989f1-4332-4014-bec3-43ded14ee071 CSeq: 25607 INVITE Server: PBXe 1.4.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Contact: Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 263 v=0 o=- 3641189659 3641189661 IN IP4 192.168.1.127 s=Asterisk c=IN IP4 192.168.1.127 t=0 0 m=audio 18892 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ...State changed from Proceeding to Completed, event=TX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ....Transaction tsx0x7fc678012728 state changed to Completed [May 21 12:34:20] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=25607 (rdata0x7fc69000d398) [May 21 12:34:20] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (368 bytes) from UDP:192.168.1.2:58557 ---> ACK sip:192.168.1.127:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:58557;rport;branch=z9hG4bKPj-XDBYy9ixsIsnqQhMQa-9doa9mQO95zL Max-Forwards: 70 From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=923989f1-4332-4014-bec3-43ded14ee071 Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ CSeq: 25607 ACK Content-Length: 0 [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONNECTING [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 200 OK [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fc678012728) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONNECTING [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is INVITE, Response is 200 OK [May 21 12:34:20] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg UPDATE/cseq=25608 (rdata0x7fc69000d398) [May 21 12:34:20] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (821 bytes) from UDP:192.168.1.2:58557 ---> UPDATE sip:192.168.1.127:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:58557;rport;branch=z9hG4bKPj.R.-zGfMm9Vj8X8bXwbnBp0p12Hg-4MG Max-Forwards: 70 From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=923989f1-4332-4014-bec3-43ded14ee071 Contact: "71" Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ CSeq: 25608 UPDATE Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800;refresher=uac Min-SE: 90 Content-Type: application/sdp Content-Length: 271 v=0 o=- 3641189659 3641189660 IN IP4 192.168.1.2 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4188 RTP/AVP 0 101 c=IN IP4 192.168.1.2 b=TIAS:64000 a=rtcp:4189 IN IP4 192.168.1.2 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[32180][C-00000002] res_rtp_asterisk.c: Got RTCP report of 64 bytes [May 21 12:34:20] DEBUG[32180][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 21 12:34:20] DEBUG[32180][C-00000002] netsock2.c: Splitting 'ubuntu' into... [May 21 12:34:20] DEBUG[32180][C-00000002] netsock2.c: ...host 'ubuntu' and port ''. [May 21 12:34:20] DEBUG[32184] res_ari.c: Examining ARI response: 204 No Content [May 21 12:34:20] DEBUG[32184] http.c: HTTP closing session. status_code:204 [May 21 12:34:20] DEBUG[32180][C-00000002] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 21 12:34:20] DEBUG[32180][C-00000002] acl.c: Attached to given IP address [May 21 12:34:20] DEBUG[31945] netsock2.c: Splitting '192.168.1.2:4189' into... [May 21 12:34:20] DEBUG[31945] netsock2.c: ...host '192.168.1.2' and port '4189'. [May 21 12:34:20] DEBUG[31945] netsock2.c: Splitting '127.0.1.1:0' into... [May 21 12:34:20] DEBUG[31945] netsock2.c: ...host '127.0.1.1' and port '0'. [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: PJSIP/71-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 71 CallerIDName: 71 ConnectedLineNum: ConnectedLineName: Language: ru AccountCode: Context: node Exten: 72 Priority: 1 Uniqueid: 1432200858.8 To: 127.0.1.1:0 From: 192.168.1.2:4189 RTT: 0.0000 SSRC: 0x67a24c62 PT: 201(RR) ReportCount: 1 Report0SourceSSRC: 0x00000000 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 0 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [May 21 12:34:20] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=25607 (rdata0x7fc690028688) [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e .Received Request msg ACK/cseq=25607 (rdata0x7fc690028688) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ..Request to terminate transaction [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ...State changed from Completed to Terminated, event=USER [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ....Transaction tsx0x7fc678012728 state changed to Terminated [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Terminated [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is USER [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONNECTING [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:20] DEBUG[32185] http.c: HTTP opening session. Top level [May 21 12:34:20] DEBUG[32180][C-00000002] res_rtp_asterisk.c: 0x7fc67802a100 -- Probation learning mode pass with source address 192.168.1.2:4188 [May 21 12:34:20] VERBOSE[32180][C-00000002] res_rtp_asterisk.c: 0x7fc67802a100 -- Probation passed - setting RTP source address to 192.168.1.2:4188 [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc678012 Timeout timer event [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc678012 .State changed from Terminated to Destroyed, event=TIMER [May 21 12:34:20] DEBUG[31912] pjsip: tdta0x7fc67803 ..Destroying txdata Response msg 200/INVITE/cseq=25607 (tdta0x7fc67803da50) [May 21 12:34:20] DEBUG[31912] pjsip: tsx0x7fc678012 Transaction destroyed! [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Received request [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is ACK [May 21 12:34:20] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg UPDATE/cseq=25608 (rdata0x7fc690023df8) [May 21 12:34:20] DEBUG[32185] http.c: HTTP Request URI is /ari/bridges?type=mixing&bridgeId=43001b65-df5b-4ee5-9d1e-b4c238126020& [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e .Received Request msg UPDATE/cseq=25608 (rdata0x7fc690023df8) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ...Transaction created for Request msg UPDATE/cseq=25608 (rdata0x7fc690023df8) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ..Incoming Request msg UPDATE/cseq=25608 (rdata0x7fc690023df8) in state Null [May 21 12:34:20] DEBUG[32185] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [May 21 12:34:20] DEBUG[32185] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [May 21 12:34:20] DEBUG[32185] http.c: match request [ari/bridges] with handler [static] len 6 [May 21 12:34:20] DEBUG[32185] http.c: match request [ari/bridges] with handler [ari] len 3 [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ...State changed from Null to Trying, event=RX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ....Transaction tsx0x7fc678012728 state changed to Trying [May 21 12:34:20] DEBUG[32185] http.c: Match made with [ari] [May 21 12:34:20] DEBUG[32185] res_ari.c: Finding handler for bridges [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc67801e .....Got SDP offer in Request msg UPDATE/cseq=25608 (rdata0x7fc690023df8) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking endpoints [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking recordings [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking asterisk [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking sounds [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking playbacks [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking channels [May 21 12:34:20] DEBUG[32185] res_ari.c: Checking bridges [May 21 12:34:20] DEBUG[32185] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32185] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 0 (0x7fc678038968) based on m type on 0x7fc6741350d0 [May 21 12:34:20] DEBUG[32185] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [May 21 12:34:20] DEBUG[32185] bridge_native_rtp.c: Bridge '43001b65-df5b-4ee5-9d1e-b4c238126020' can not use native RTP bridge as two channels are required [May 21 12:34:20] DEBUG[32185] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 21 12:34:20] DEBUG[32185] bridge.c: Chose bridge technology simple_bridge [May 21 12:34:20] DEBUG[32185] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: calling simple_bridge technology constructor [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 101 (0x7fc678038968) based on m type on 0x7fc6741350d0 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 0 (0x7fc67802e7b8) from 0x7fc6741350d0 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[32185] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: calling simple_bridge technology start [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 43001b65-df5b-4ee5-9d1e-b4c238126020 BridgeType: stasis BridgeTechnology: simple_bridge BridgeCreator: Stasis BridgeName: BridgeNumChannels: 0 [May 21 12:34:20] DEBUG[32185] res_ari.c: Examining ARI response: 200 OK Content-type: application/json { "id": "43001b65-df5b-4ee5-9d1e-b4c238126020", "technology": "simple_bridge", "bridge_type": "mixing", "bridge_class": "stasis", "creator": "Stasis", "name": "", "channels": [] } [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 101 (0x7fc6780300a8) from 0x7fc6741350d0 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Media stream 'audio' handled by audio [May 21 12:34:20] DEBUG[32185] http.c: HTTP closing session. status_code:200 [May 21 12:34:20] DEBUG[31907] pjsip: inv0x7fc67801e .....SDP negotiation done, status=0 [May 21 12:34:20] DEBUG[32186] http.c: HTTP opening session. Top level [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:20] DEBUG[31907] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc678033028' [May 21 12:34:20] DEBUG[32186] http.c: HTTP Request URI is /ari/bridges/43001b65-df5b-4ee5-9d1e-b4c238126020/addChannel?channel=1432200858.8%2C333dc9d9-a3de-4fcc-a023-5c04f7ffac3f& [May 21 12:34:20] DEBUG[32186] http.c: match request [ari/bridges/43001b65-df5b-4ee5-9d1e-b4c238126020/addChannel] with handler [httpstatus] len 10 [May 21 12:34:20] DEBUG[32186] http.c: match request [ari/bridges/43001b65-df5b-4ee5-9d1e-b4c238126020/addChannel] with handler [phoneprov] len 9 [May 21 12:34:20] DEBUG[32186] http.c: match request [ari/bridges/43001b65-df5b-4ee5-9d1e-b4c238126020/addChannel] with handler [static] len 6 [May 21 12:34:20] DEBUG[32186] http.c: match request [ari/bridges/43001b65-df5b-4ee5-9d1e-b4c238126020/addChannel] with handler [ari] len 3 [May 21 12:34:20] DEBUG[32186] http.c: Match made with [ari] [May 21 12:34:20] DEBUG[32186] res_ari.c: Finding handler for bridges [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking endpoints [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking recordings [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking asterisk [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking sounds [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking playbacks [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking channels [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking bridges [May 21 12:34:20] DEBUG[32186] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32186] res_ari.c: Finding handler for 43001b65-df5b-4ee5-9d1e-b4c238126020 [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking bridgeId [May 21 12:34:20] DEBUG[32186] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32186] res_ari.c: Finding handler for addChannel [May 21 12:34:20] DEBUG[32186] res_ari.c: Checking addChannel [May 21 12:34:20] DEBUG[32186] res_ari.c: Got it! [May 21 12:34:20] DEBUG[32186] bridge_roles.c: Roles did not exist on channel PJSIP/71-00000004 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 0 (0x7fc678038968) based on m type on 0x7fc674134b90 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Setting payload 101 (0x7fc678038968) based on m type on 0x7fc674134b90 [May 21 12:34:20] DEBUG[32186] bridge_roles.c: Roles did not exist on channel PJSIP/502-00000005 [May 21 12:34:20] DEBUG[32186] stasis/control.c: 1432200858.8: Sending channel add_to_bridge command [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 0 (0x7fc67804d488) from 0x7fc674134b90 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Copying payload 101 (0x7fc678056de8) from 0x7fc674134b90 to 0x7fc6780331f0 [May 21 12:34:20] DEBUG[32180][C-00000002] stasis/control.c: 1432200858.8: Adding to bridge 43001b65-df5b-4ee5-9d1e-b4c238126020 [May 21 12:34:20] DEBUG[32180][C-00000002] stasis/app.c: Bridge '43001b65-df5b-4ee5-9d1e-b4c238126020' is 1 interested in pbxe [May 21 12:34:20] DEBUG[32180][C-00000002] stasis/app.c: Bridge '43001b65-df5b-4ee5-9d1e-b4c238126020' is 2 interested in pbxe [May 21 12:34:20] DEBUG[32186] stasis/control.c: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f: Sending channel add_to_bridge command [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [May 21 12:34:20] DEBUG[31907] pjsip: endpoint .....Response msg 200/UPDATE/cseq=25608 (tdta0x7fc6900176f0) created [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ......Sending Response msg 200/UPDATE/cseq=25608 (tdta0x7fc6900176f0) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 ......Sending Response msg 200/UPDATE/cseq=25608 (tdta0x7fc6900176f0) in state Trying [May 21 12:34:20] DEBUG[31907] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 192.168.1.127:5060 [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port ''. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.2:58557' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.2' and port '58557'. [May 21 12:34:20] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (900 bytes) to UDP:192.168.1.2:58557 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.2:58557;rport=58557;received=192.168.1.2;branch=z9hG4bKPj.R.-zGfMm9Vj8X8bXwbnBp0p12Hg-4MG Call-ID: xA8INf7kkBjw7Pvwkd.AQ8NZZpAae.RZ From: "71" ;tag=gGfwW1WaUpsNblDwn4H24XjEaE4AcYZV To: ;tag=923989f1-4332-4014-bec3-43ded14ee071 CSeq: 25608 UPDATE Session-Expires: 1800;refresher=uac Require: timer Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REGISTER, REFER Supported: 100rel, timer, replaces, norefersub Server: PBXe 1.4.0 Content-Type: application/sdp Content-Length: 239 v=0 o=- 3641189659 3641189662 IN IP4 192.168.1.127 s=Asterisk c=IN IP4 192.168.1.127 t=0 0 m=audio 18892 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 [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc678012 .......State changed from Trying to Completed, event=TX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc67801e ........Transaction tsx0x7fc678012728 state changed to Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS UPDATE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:20] DEBUG[32187][C-00000002] bridge_channel.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: 0x2a89228(PJSIP/71-00000004) is joining [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is UPDATE, Response is 200 OK [May 21 12:34:20] DEBUG[32187][C-00000002] bridge_channel.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: pushing 0x2a89228(PJSIP/71-00000004) [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '71(PJSIP/71-00000004)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS UPDATE transaction involved in this state change is 0x7fc678012728 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Received request [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is UPDATE [May 21 12:34:20] VERBOSE[32187][C-00000002] bridge_channel.c: Channel PJSIP/71-00000004 joined 'simple_bridge' stasis-bridge <43001b65-df5b-4ee5-9d1e-b4c238126020> [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 43001b65-df5b-4ee5-9d1e-b4c238126020 BridgeType: stasis BridgeTechnology: simple_bridge BridgeCreator: Stasis BridgeName: BridgeNumChannels: 1 Channel: PJSIP/71-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 71 CallerIDName: 71 ConnectedLineNum: ConnectedLineName: Language: ru AccountCode: Context: node Exten: 72 Priority: 1 Uniqueid: 1432200858.8 [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "ChannelEnteredBridge", "timestamp": "2015-05-21T12:34:20.460+0300", "bridge": { "id": "43001b65-df5b-4ee5-9d1e-b4c238126020", "technology": "simple_bridge", "bridge_type": "mixing", "bridge_class": "stasis", "creator": "Stasis", "name": "", "channels": [ "1432200858.8" ] }, "channel": { "id": "1432200858.8", "name": "PJSIP/71-00000004", "state": "Up", "caller": { "name": "71", "number": "71" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "node", "exten": "72", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.602+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 21 12:34:20] DEBUG[32187][C-00000002] bridge_native_rtp.c: Bridge '43001b65-df5b-4ee5-9d1e-b4c238126020' can not use native RTP bridge as two channels are required [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Chose bridge technology simple_bridge [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020 is already using the new technology. [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020 is happy that channel PJSIP/71-00000004 already has read format ulaw [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020 is happy that channel PJSIP/71-00000004 already has write format ulaw [May 21 12:34:20] DEBUG[32187][C-00000002] bridge.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: 0x2a89228(PJSIP/71-00000004) is joining simple_bridge technology [May 21 12:34:20] DEBUG[32187][C-00000002] res_rtp_asterisk.c: 0x7fc67802a100 -- Probation learning mode pass with source address 192.168.1.2:4188 [May 21 12:34:20] VERBOSE[32187][C-00000002] res_rtp_asterisk.c: 0x7fc67802a100 -- Probation passed - setting RTP source address to 192.168.1.2:4188 [May 21 12:34:20] DEBUG[31912] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=101 (rdata0x7fc69000d398) [May 21 12:34:20] VERBOSE[31912] res_pjsip_logger.c: <--- Received SIP request (395 bytes) from UDP:192.168.1.50:5060 ---> BYE sip:5fe3da24-c3d0-4d52-bdd9-e76065119a1e@192.168.1.127:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.50:5060;branch=z9hG4bK-9b6d9a12 From: ;tag=e394cd5176fe64a8i0 To: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b CSeq: 101 BYE Max-Forwards: 70 User-Agent: Cisco/SPA502G-7.4.8a Content-Length: 0 [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:20] DEBUG[31912] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31912] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=101 (rdata0x7fc690024b28) [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 .Received Request msg BYE/cseq=101 (rdata0x7fc690024b28) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d ...Transaction created for Request msg BYE/cseq=101 (rdata0x7fc690024b28) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d ..Incoming Request msg BYE/cseq=101 (rdata0x7fc690024b28) in state Null [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d ...State changed from Null to Trying, event=RX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ....Transaction tsx0x7fc67802d0b8 state changed to Trying [May 21 12:34:20] DEBUG[31907] pjsip: endpoint .....Response msg 200/BYE/cseq=101 (tdta0x7fc67803da50) created [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ......Sending Response msg 200/BYE/cseq=101 (tdta0x7fc67803da50) [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d ......Sending Response msg 200/BYE/cseq=101 (tdta0x7fc67803da50) in state Trying [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.50' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port ''. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.127:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.127' and port '5060'. [May 21 12:34:20] DEBUG[31907] netsock2.c: Splitting '192.168.1.50:5060' into... [May 21 12:34:20] DEBUG[31907] netsock2.c: ...host '192.168.1.50' and port '5060'. [May 21 12:34:20] VERBOSE[31907] res_pjsip_logger.c: <--- Transmitting SIP response (340 bytes) to UDP:192.168.1.50:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.50:5060;rport=5060;received=192.168.1.50;branch=z9hG4bK-9b6d9a12 Call-ID: f6fb0222-e1fe-4326-949b-0fd21ad72e2b From: ;tag=e394cd5176fe64a8i0 To: "71" ;tag=5ebcbefe-1fce-490d-bab1-bbfebb9040ca CSeq: 101 BYE Server: PBXe 1.4.0 Content-Length: 0 [May 21 12:34:20] DEBUG[31907] pjsip: tsx0x7fc67802d .......State changed from Trying to Completed, event=TX_MSG [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ........Transaction tsx0x7fc67802d0b8 state changed to Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is TX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is CONFIRMED [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Sending response [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is BYE, Response is 200 OK [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The state change pertains to the endpoint '502(PJSIP/502-00000005)' [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: There is no transaction involved in this state change [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is DISCONNCTD [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Received request [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Method is BYE [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f Cause: 16 [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "cause": 16, "type": "ChannelHangupRequest", "timestamp": "2015-05-21T12:34:20.551+0300", "channel": { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[32182] stasis/control.c: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f: Adding to bridge 43001b65-df5b-4ee5-9d1e-b4c238126020 [May 21 12:34:20] DEBUG[32182] stasis/app.c: Bridge '43001b65-df5b-4ee5-9d1e-b4c238126020' is 3 interested in pbxe [May 21 12:34:20] DEBUG[32182] res_stasis.c: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f: Hangup (no more frames) [May 21 12:34:20] DEBUG[32182] stasis/app.c: bridge '43001b65-df5b-4ee5-9d1e-b4c238126020': is 2 interested in pbxe [May 21 12:34:20] DEBUG[32182] stasis/app.c: channel '333dc9d9-a3de-4fcc-a023-5c04f7ffac3f': is 1 interested in pbxe [May 21 12:34:20] DEBUG[32182] channel.c: Hanging up channel 'PJSIP/502-00000005' [May 21 12:34:20] DEBUG[32182] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [May 21 12:34:20] DEBUG[32186] res_ari.c: Examining ARI response: 204 No Content [May 21 12:34:20] DEBUG[32186] http.c: HTTP closing session. status_code:204 [May 21 12:34:20] DEBUG[31985] ari/ari_websockets.c: Examining ARI event: { "type": "StasisEnd", "timestamp": "2015-05-21T12:34:20.558+0300", "channel": { "id": "333dc9d9-a3de-4fcc-a023-5c04f7ffac3f", "name": "PJSIP/502-00000005", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "71", "number": "71" }, "accountcode": "", "dialplan": { "context": "dialmap", "exten": "s", "priority": 1 }, "creationtime": "2015-05-21T12:34:18.616+0300", "language": "ru" }, "application": "pbxe" } [May 21 12:34:20] DEBUG[31907] pjsip: tdta0x7fc67001 .....Destroying txdata Request msg ACK/cseq=15124 (tdta0x7fc67001c290) [May 21 12:34:20] DEBUG[31907] pjsip: tdta0x7fc69001 .....Destroying txdata Request msg INVITE/cseq=15124 (tdta0x7fc69001e0b0) [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 ......Session count dec to 4 by mod-invite [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: inv_session 0x7fc678042608 has no ast session [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fc67802d0b8 [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current transaction state is Completed [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The transaction state change event is RX_MSG [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: The current inv state is DISCONNCTD [May 21 12:34:20] DEBUG[31907] res_pjsip_session.c: Destroying SIP session with endpoint 502 [May 21 12:34:20] DEBUG[31907] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fc67801f438' [May 21 12:34:20] DEBUG[31907] rtp_engine.c: Destroyed RTP instance '0x7fc67801f438' [May 21 12:34:20] DEBUG[31907] pjsip: dlg0x7fc678041 .Session count dec to 0 by Session Module [May 21 12:34:20] DEBUG[32188] bridge_channel.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: 0x7fc690018978(PJSIP/502-00000005) is joining [May 21 12:34:20] DEBUG[32188] bridge_channel.c: Bridge 43001b65-df5b-4ee5-9d1e-b4c238126020: 0x7fc690018978(PJSIP/502-00000005) failed to join Bridge [May 21 12:34:20] DEBUG[31897] cdr.c: Finalized CDR for PJSIP/502-00000005 - start 1432200858.617138 answer 1432200860.366455 end 1432200860.561310 dispo ANSWERED [May 21 12:34:20] DEBUG[31971] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/502-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: 71 ConnectedLineName: 71 Language: ru AccountCode: Context: dialmap Exten: s Priority: 1 Uniqueid: 333dc9d9-a3de-4fcc-a023-5c04f7ffac3f Cause: 16 Cause-txt: Normal Clearing [May 21 12:34:20] ERROR[32188] astobj2.c: bad magic number for object 0x7fc690028418. Object is likely destroyed.