[May 28 15:51:39] Asterisk 12.2.0 built by root @ localhost.localdomain on a x86_64 running Linux on 2014-05-23 07:05:38 UTC [May 28 15:51:39] NOTICE[4570] loader.c: 2 modules will be loaded. [May 28 15:51:39] NOTICE[4570] res_odbc.c: Connecting asterisk [May 28 15:51:39] NOTICE[4570] res_odbc.c: res_odbc: Connected to asterisk [asterisk] [May 28 15:51:39] NOTICE[4570] res_odbc.c: Registered ODBC class 'asterisk' dsn->[asterisk] [May 28 15:51:39] NOTICE[4570] res_odbc.c: Connecting proxy [May 28 15:51:39] NOTICE[4570] res_odbc.c: res_odbc: Connected to proxy [proxy] [May 28 15:51:39] NOTICE[4570] res_odbc.c: Registered ODBC class 'proxy' dsn->[proxy] [May 28 15:51:39] NOTICE[4570] res_odbc.c: res_odbc loaded. [May 28 15:51:39] NOTICE[4570] config.c: Registered Config Engine odbc [May 28 15:51:39] NOTICE[4570] cdr.c: CDR simple logging enabled. [May 28 15:51:39] NOTICE[4570] loader.c: 266 modules will be loaded. [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:172.16.99.2:5060 freq=60 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000001@192.168.166.13:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000002@192.168.166.13:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000003@192.168.166.13:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000004@192.168.166.13:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000005@172.16.99.2:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000006@95.154.112.16:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000007@172.16.99.2:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000008@95.154.112.16:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip000009@95.154.112.16:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip111110@95.154.112.16:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip111111@95.154.112.16:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip123456@172.16.99.2:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_pjsip/pjsip_options.c: BUGBUG contact sip:sip654321@172.16.99.2:5060 freq=0 auth=0 [May 28 15:51:40] NOTICE[4570] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener. [May 28 15:51:40] ERROR[4570] ari/config.c: No configured users for ARI [May 28 15:51:40] WARNING[4570] loader.c: Error loading module 'res_ari_mailboxes.so': /usr/lib64/asterisk/modules/res_ari_mailboxes.so: undefined symbol: stasis_app_mailbox_update [May 28 15:51:40] WARNING[4570] loader.c: Module 'res_ari_mailboxes.so' could not be loaded. [May 28 15:51:40] NOTICE[4592] res_pjsip/pjsip_distributor.c: Request from '' failed for '172.16.99.2:5060' (callid: 4c2d860e28418b6a-2287@172.16.99.2) - No matching endpoint found [May 28 15:51:40] WARNING[4592] res_pjsip.c: No SIP authenticator registered. Assuming authentication is not required [May 28 15:51:40] NOTICE[4570] config.c: Registered Config Engine curl [May 28 15:51:40] NOTICE[4570] config.c: Registered Config Engine sqlite3 [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database user found, using 'asterisk' as default. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database password found, using 'asterisk' as default. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database host found, using localhost via socket. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database name found, using 'asterisk' as default. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database port found, using 3306 as default. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database socket found, using '/var/lib/mysql/mysql.sock' as default. [May 28 15:51:40] WARNING[4570] res_config_mysql.c: MySQL RealTime: No database socket found (and unable to detect a suitable path). [May 28 15:51:40] NOTICE[4570] config.c: Registered Config Engine mysql [May 28 15:51:40] NOTICE[4570] cel_custom.c: No mappings found in cel_custom.conf. Not logging CEL to custom CSVs. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: Starting AEL load process. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: AEL load process: parsed config file name '/etc/asterisk/extensions.ael'. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: AEL load process: checked config file name '/etc/asterisk/extensions.ael'. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: AEL load process: compiled config file name '/etc/asterisk/extensions.ael'. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: AEL load process: merged config file name '/etc/asterisk/extensions.ael'. [May 28 15:51:40] NOTICE[4570] pbx_ael.c: AEL load process: verified config file name '/etc/asterisk/extensions.ael'. [May 28 15:51:40] WARNING[4570] app_voicemail.c: maxsilence should be less than minsecs or you may get empty messages [May 28 15:51:40] NOTICE[4570] app_queue.c: No entries were found for ringinuse/ignorebusy in queue_members table. Using 'ringinuse' [May 28 15:51:40] VERBOSE[4570] asterisk.c: Asterisk Ready. [May 28 15:51:43] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (639 bytes) from UDP:172.16.99.2:5060 ---> ˙REGISTER sip:172.16.99.9:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bK18ff.a77befd5.0 ˙Via: SIP/2.0/UDP 172.16.99.241:5065;received=172.16.99.241;rport=5065;branch=z9hG4bKPj24d5fdc0-60a8-4b45-802d-e81f7dd54e37 ˙Max-Forwards: 69 ˙From: ;tag=4eb5e76e-5ebc-4de7-91c7-f7f0254ea83f ˙To: ˙Call-ID: 59d57706-dd30-49f2-b687-b304e212c797 ˙CSeq: 46976 REGISTER ˙User-Agent: SFLphone/1.3.0 ˙Contact: ˙Expires: 60 ˙Allow: PRACK, SUBSCRIBE, NOTIFY, REFER, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, OPTIONS, MESSAGE, PUBLISH ˙Content-Length: 0 ˙ ˙ [May 28 15:51:43] VERBOSE[4593] res_pjsip_logger.c: <--- Transmitting SIP response (620 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bK18ff.a77befd5.0 ˙Via: SIP/2.0/UDP 172.16.99.241:5065;rport=5065;received=172.16.99.241;branch=z9hG4bKPj24d5fdc0-60a8-4b45-802d-e81f7dd54e37 ˙Call-ID: 59d57706-dd30-49f2-b687-b304e212c797 ˙From: ;tag=4eb5e76e-5ebc-4de7-91c7-f7f0254ea83f ˙To: ;tag=z9hG4bK18ff.a77befd5.0 ˙CSeq: 46976 REGISTER ˙Date: Wed, 28 May 2014 04:51:43 GMT ˙Contact: ;expires=59 ˙Contact: ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:51:46] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (359 bytes) from UDP:172.16.99.2:5060 ---> ˙OPTIONS sip:172.16.99.9:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bKf63.5b6e3a1.0 ˙To: sip:172.16.99.9:5060 ˙From: ;tag=28892ca7cba2b104f2577d65fc0fc8bd-b173 ˙CSeq: 10 OPTIONS ˙Call-ID: 4c2d860e28418b6b-2287@172.16.99.2 ˙Max-Forwards: 70 ˙Content-Length: 0 ˙User-Agent: OpenSIPS (1.11.1-notls (x86_64/linux)) ˙ ˙ [May 28 15:51:46] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP response (773 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 404 Not Found ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bKf63.5b6e3a1.0 ˙Call-ID: 4c2d860e28418b6b-2287@172.16.99.2 ˙From: ;tag=28892ca7cba2b104f2577d65fc0fc8bd-b173 ˙To: ;tag=z9hG4bKf63.5b6e3a1.0 ˙CSeq: 10 OPTIONS ˙Accept: application/sdp, application/pidf+xml, application/simple-message-summary, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, message/sipfrag;version=2.0 ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER ˙Supported: 100rel, timer, replaces, norefersub ˙Accept-Encoding: text/plain ˙Accept-Language: en ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:04] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=843806 (rdata0x7f4b0c0028d8) [May 28 15:52:04] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (1096 bytes) from UDP:172.16.99.2:5060 ---> ˙INVITE sip:4232050001@172.16.99.2:5060 SIP/2.0 ˙Record-Route: ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bKf243.247a1fe2.0 ˙Via: SIP/2.0/UDP 172.16.99.1:5060;received=172.16.99.1;rport=5060;branch=z9hG4bK-o25843889533782139396156 ˙From: "9940077312" ;tag=843813252974 ˙To: ˙Call-ID: 1401-252974-844422 ˙CSeq: 843806 INVITE ˙User-Agent: Eltex smg_pa_sip 2.15.1.32 ˙Max-Forwards: 69 ˙Contact: ˙Accept: multipart/mixed, application/sdp ˙Allow: INVITE, ACK, BYE, CANCEL, PRACK, REGISTER, INFO, REFER, NOTIFY, OPTIONS, UPDATE ˙Supported: 100rel, replaces ˙Category: 10 ˙P-Eltex-Info: {trunk,2} 1133 <0.24279.4> ˙Content-Type: application/sdp ˙Content-Length: 261 ˙ ˙v=0 ˙o=- 1133 1133 IN IP4 172.16.99.1 ˙s=SMG SIP session ˙c=IN IP4 172.16.99.1 ˙t=0 0 ˙m=audio 54202 RTP/AVP 8 18 101 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:18 G729/8000 ˙a=fmtp:18 annexb=no ˙a=rtpmap:101 telephone-event/8000 ˙a=fmtp:101 0-15 ˙a=ptime:30 ˙a=sendrecv ˙ [May 28 15:52:04] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=843806 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = '9940077312@172.16.99.1' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = '9940077312' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username '9940077312' [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:04] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:04] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:04] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:04] DEBUG[4592] acl.c: 172.16.99.2:0/255.255.255.255:0 sense 0 appended to ACL [May 28 15:52:04] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:04] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:04] DEBUG[4592] res_pjsip_endpoint_identifier_ip.c: Source address 172.16.99.2:5060 matches identify 'opensips' [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'opensips' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint opensips [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18016 ..Transaction created for Request msg INVITE/cseq=843806 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18016 .Incoming Request msg INVITE/cseq=843806 (rdata0x7f4b0c009528) in state Null [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18016 ..State changed from Null to Trying, event=RX_MSG [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 ...Transaction tsx0x7f4b180164a8 state changed to Trying [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 .UAS dialog created [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 .Module mod-invite added as dialog usage, data=0x7f4b18018dd8 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 ..Session count inc to 2 by mod-invite [May 28 15:52:04] DEBUG[4592] pjsip: inv0x7f4b18005 .UAS invite session created for dialog dlg0x7f4b18005248 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 .Module Session Module added as dialog usage, data=(nil) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 ..Session count inc to 2 by Session Module [May 28 15:52:04] DEBUG[4593] netsock2.c: Splitting '172.16.99.1' into... [May 28 15:52:04] DEBUG[4593] netsock2.c: ...host '172.16.99.1' and port ''. [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f4b0c00b4a8' [May 28 15:52:04] DEBUG[4593] res_rtp_asterisk.c: Allocated port 18028 for RTP instance '0x7f4b0c00b4a8' [May 28 15:52:04] DEBUG[4593] pjsip: icess0x7f4b0c0 ICE session created, comp_cnt=2, role is Unknown agent [May 28 15:52:04] DEBUG[4593] netsock2.c: Splitting '172.16.99.9' into... [May 28 15:52:04] DEBUG[4593] netsock2.c: ...host '172.16.99.9' and port ''. [May 28 15:52:04] DEBUG[4593] pjsip: icess0x7f4b0c0 Candidate 0 added: comp_id=1, type=host, foundation=Hac106309, addr=172.16.99.9:18028, base=172.16.99.9:18028, prio=0x7effffff (2130706431) [May 28 15:52:04] DEBUG[4593] rtp_engine.c: RTP instance '0x7f4b0c00b4a8' is setup and ready to go [May 28 15:52:04] DEBUG[4593] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f4b0c00b4a8' [May 28 15:52:04] DEBUG[4593] netsock2.c: Splitting '172.16.99.9' into... [May 28 15:52:04] DEBUG[4593] netsock2.c: ...host '172.16.99.9' and port ''. [May 28 15:52:04] DEBUG[4593] pjsip: icess0x7f4b0c0 Candidate 1 added: comp_id=2, type=host, foundation=Hac106309, addr=172.16.99.9:18029, base=172.16.99.9:18029, prio=0x7efffffe (2130706430) [May 28 15:52:04] DEBUG[4593] pjsip: icess0x7f4b0c0 Destroying ICE session 0x7f4b0c0132d8 [May 28 15:52:04] DEBUG[4593] pjsip: stuse0x7f4b0c0 STUN session 0x7f4b0c015908 destroy request, ref_cnt=4 [May 28 15:52:04] DEBUG[4593] pjsip: stuse0x7f4b0c0 STUN session 0x7f4b0c016908 destroy request, ref_cnt=3 [May 28 15:52:04] DEBUG[4593] pjsip: ice_session.c ICE session 0x7f4b0c0132d8 destroyed [May 28 15:52:04] DEBUG[4593] pjsip: stun_session.c STUN session 0x7f4b0c015908 destroyed [May 28 15:52:04] DEBUG[4593] pjsip: stun_session.c STUN session 0x7f4b0c016908 destroyed [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Setting payload 8 based on m type on 0x7f4b00491fb0 [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Setting payload 18 based on m type on 0x7f4b00491fb0 [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Setting payload 101 based on m type on 0x7f4b00491fb0 [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Copying payload 8 from 0x7f4b00491fb0 to 0x7f4b0c00b5e8 [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Copying payload 18 from 0x7f4b00491fb0 to 0x7f4b0c00b5e8 [May 28 15:52:04] DEBUG[4593] rtp_engine.c: Copying payload 101 from 0x7f4b00491fb0 to 0x7f4b0c00b5e8 [May 28 15:52:04] DEBUG[4593] pjsip: endpoint .Response msg 100/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) created [May 28 15:52:04] DEBUG[4593] pjsip: dlg0x7f4b18005 .Initial answer Response msg 100/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [May 28 15:52:04] DEBUG[4593] pjsip: inv0x7f4b18005 .Sending Response msg 100/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:04] DEBUG[4593] pjsip: dlg0x7f4b18005 ..Sending Response msg 100/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:04] DEBUG[4593] pjsip: tsx0x7f4b18016 ..Sending Response msg 100/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) in state Trying [May 28 15:52:04] VERBOSE[4593] res_pjsip_logger.c: <--- Transmitting SIP response (509 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bKf243.247a1fe2.0 ˙Via: SIP/2.0/UDP 172.16.99.1:5060;rport=5060;received=172.16.99.1;branch=z9hG4bK-o25843889533782139396156 ˙Record-Route: ˙Call-ID: 1401-252974-844422 ˙From: "9940077312" ;tag=843813252974 ˙To: ˙CSeq: 843806 INVITE ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:04] DEBUG[4593] pjsip: tsx0x7f4b18016 ...State changed from Trying to Proceeding, event=TX_MSG [May 28 15:52:04] DEBUG[4593] pjsip: dlg0x7f4b18005 ....Transaction tsx0x7f4b180164a8 state changed to Proceeding [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The current inv state is INCOMING [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Sending response [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The current transaction state is Proceeding [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: The current inv state is INCOMING [May 28 15:52:04] DEBUG[4593] res_pjsip_session.c: Method is INVITE [May 28 15:52:04] DEBUG[4593] pjsip: dlg0x7f4b18005 Module NAT added as dialog usage, data=(nil) [May 28 15:52:04] DEBUG[4593] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/opensips-00000000 [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function CALLERID(num) result is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'EXTEN' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'EXTEN' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'EXTEN' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Macro' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_IP' is '172.16.99.2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_USER' is 'asterisk' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_PASS' is '123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_PBX' is 'virtualpbx' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Connect connid 172.16.99.2 asterisk 123456 virtualpbx [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'connid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Query resultid 1 SELECT id FROM phones WHERE num="4232050001" [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'resultid' to value '2' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Fetch fetchid 2 PHONE_ID [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: ast_MYSQL_fetch: numFields=1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'fetchid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Clear 2 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'PHONE_ID' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Query resultid 1 SELECT username FROM sip_users WHERE phone_id="2" [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'resultid' to value '2' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Fetch fetchid 2 USERNAME [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: ast_MYSQL_fetch: numFields=1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'fetchid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is '_USER' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USERNAME' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Fetch fetchid 2 USERNAME [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: ast_MYSQL_fetch : EOF [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'fetchid' to value '0' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Clear 2 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Disconnect 1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'fetchid' (from 'fetchid}" = "1"' len 7) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG4' is 'RCODE' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'fetchid' (from 'fetchid}" = "1"' len 7) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG4' (from 'ARG4}=1)' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG4' is 'RCODE' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'fetchid' (from 'fetchid}" = "1"' len 7) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_IP' is '172.16.99.2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_USER' is 'asterisk' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_PASS' is '123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_OPENSIPS' is 'opensips_1_11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Connect connid 172.16.99.2 asterisk 123456 opensips_1_11 [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'connid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USERNAME' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Query resultid 1 SELECT password FROM subscriber WHERE username="sip123456" [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'resultid' to value '2' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Fetch fetchid 2 PASSWORD [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: ast_MYSQL_fetch: numFields=1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'fetchid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Clear 2 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Disconnect 1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'fetchid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG3' is 'SECRET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'PASSWORD' is '123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG4' is 'RCODE' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MacroExit' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'RCODE' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'RCODE' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DST' is NULL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'AGI' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function CALLERID(num) result is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Macro' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_IP' is '172.16.99.2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_USER' is 'asterisk' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_PASS' is '123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'DB_PBX' is 'virtualpbx' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Connect connid 172.16.99.2 asterisk 123456 virtualpbx [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'connid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Query resultid 1 SELECT target,type FROM service_cf WHERE username="sip123456" [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'resultid' to value '2' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is 'CF_TARGET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG3' is '_CF_TYPE' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Fetch fetchid 2 CF_TARGET _CF_TYPE [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: ast_MYSQL_fetch: numFields=2 [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: setting var 'fetchid' to value '1' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'resultid' is '2' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Clear 2 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'MYSQL_STATUS' is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'connid' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MYSQL' [May 28 15:52:04] DEBUG[4651][C-00000000] app_mysql.c: MYSQL: data=Disconnect 1 [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: MYSQL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'MacroExit' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'RCODE' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'RCODE' is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TARGET' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is '_UTM5_CF_TARGET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'LEN(${ARG1})' (from 'LEN(${ARG1})} = 7' len 12) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1' (from 'ARG1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG2' (from 'ARG2}=423${ARG1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is '_UTM5_CF_TARGET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1' (from 'ARG1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'LEN(${ARG1})' (from 'LEN(${ARG1})} = 7' len 12) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1' (from 'ARG1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is '_UTM5_CF_TARGET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1:0:1' (from 'ARG1:0:1} = 8' len 8) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'LEN(${ARG1})' (from 'LEN(${ARG1})} = 11' len 12) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1' (from 'ARG1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG2' (from 'ARG2}=${ARG1:1})' len 4) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is '_UTM5_CF_TARGET' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1:1' (from 'ARG1:1})' len 6) [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is '89940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Function LEN(89940077312) result is '11' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_CF_TARGET' is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UUID' is '764af0f9-de3a-4997-9ca3-5d00c7cb87c9' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_SRC' is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'REDIRECTED_UUID' is NULL [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_CF_TARGET' is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UUID' is '764af0f9-de3a-4997-9ca3-5d00c7cb87c9' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_SRC' is '9940077312' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:04] DEBUG[4651][C-00000000] pbx.c: Launching 'Dial' [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 UAC dialog created [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 Module Outbound Authentica added as dialog usage, data=0x7f4b180140f0 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 Module mod-invite added as dialog usage, data=0x7f4b180145f8 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 .Session count inc to 2 by mod-invite [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 Module mod-100rel added as dialog usage, data=0x7f4b180147b8 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 100rel module attached [May 28 15:52:04] DEBUG[4592] pjsip: inv0x7f4b18015 UAC invite session created for dialog dlg0x7f4b180152e8 [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 .Session count inc to 2 by Session Module [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 Module Session Module added as dialog usage, data=(nil) [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable UTM5_CF_TARGET from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable CF_TYPE from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable UTM5_SRC from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable UUID from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable USER from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable UTM5_DST from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4651][C-00000000] channel.c: Inheriting variable CALL_TYPE from PJSIP/opensips-00000000 to PJSIP/sip123456-00000001. [May 28 15:52:04] DEBUG[4592] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f4b1802a8c8' [May 28 15:52:04] DEBUG[4592] res_rtp_asterisk.c: Allocated port 17266 for RTP instance '0x7f4b1802a8c8' [May 28 15:52:04] DEBUG[4592] pjsip: icess0x7f4b180 ICE session created, comp_cnt=2, role is Unknown agent [May 28 15:52:04] DEBUG[4592] netsock2.c: Splitting '172.16.99.9' into... [May 28 15:52:04] DEBUG[4592] netsock2.c: ...host '172.16.99.9' and port ''. [May 28 15:52:04] DEBUG[4592] pjsip: icess0x7f4b180 Candidate 0 added: comp_id=1, type=host, foundation=Hac106309, addr=172.16.99.9:17266, base=172.16.99.9:17266, prio=0x7effffff (2130706431) [May 28 15:52:04] DEBUG[4592] rtp_engine.c: RTP instance '0x7f4b1802a8c8' is setup and ready to go [May 28 15:52:04] DEBUG[4592] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f4b1802a8c8' [May 28 15:52:04] DEBUG[4592] netsock2.c: Splitting '172.16.99.9' into... [May 28 15:52:04] DEBUG[4592] netsock2.c: ...host '172.16.99.9' and port ''. [May 28 15:52:04] DEBUG[4592] pjsip: icess0x7f4b180 Candidate 1 added: comp_id=2, type=host, foundation=Hac106309, addr=172.16.99.9:17267, base=172.16.99.9:17267, prio=0x7efffffe (2130706430) [May 28 15:52:04] DEBUG[4592] pjsip: icess0x7f4b180 Destroying ICE session 0x7f4b18031a18 [May 28 15:52:04] DEBUG[4592] pjsip: stuse0x7f4b180 STUN session 0x7f4b18033a28 destroy request, ref_cnt=4 [May 28 15:52:04] DEBUG[4592] pjsip: stuse0x7f4b180 STUN session 0x7f4b18034a28 destroy request, ref_cnt=3 [May 28 15:52:04] DEBUG[4592] pjsip: ice_session.c ICE session 0x7f4b18031a18 destroyed [May 28 15:52:04] DEBUG[4592] pjsip: stun_session.c STUN session 0x7f4b18033a28 destroyed [May 28 15:52:04] DEBUG[4592] pjsip: stun_session.c STUN session 0x7f4b18034a28 destroyed [May 28 15:52:04] DEBUG[4592] pjsip: endpoint Request msg INVITE/cseq=2556 (tdta0x7f4b18004190) created. [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Method is INVITE [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 Module NAT added as dialog usage, data=(nil) [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:04] DEBUG[4592] pjsip: inv0x7f4b18015 .Sending Request msg INVITE/cseq=2556 (tdta0x7f4b18004190) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ..Sending Request msg INVITE/cseq=2556 (tdta0x7f4b18004190) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 ...Transaction created for Request msg INVITE/cseq=2555 (tdta0x7f4b18004190) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 ..Sending Request msg INVITE/cseq=2555 (tdta0x7f4b18004190) in state Null [May 28 15:52:04] DEBUG[4592] pjsip: sip_resolve.c ...Target '172.16.99.2:5060' type=Unspecified resolved to '172.16.99.2:5060' type=UDP (UDP transport) [May 28 15:52:04] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP request (964 bytes) to UDP:172.16.99.2:5060 ---> ˙INVITE sip:sip123456@172.16.99.2:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.9:5060;rport;branch=z9hG4bKPje62d7d90-484f-4833-8880-9f70bce2c04d ˙From: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙To: ˙Contact: ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 2555 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER ˙Supported: 100rel, timer, replaces, norefersub ˙Session-Expires: 1800 ˙Min-SE: 90 ˙Max-Forwards: 70 ˙User-Agent: Asterisk PBX 12 ˙Content-Type: application/sdp ˙Content-Length: 267 ˙ ˙v=0 ˙o=- 1638041549 1638041549 IN IP4 localhost.localdomain ˙s=Asterisk ˙c=IN IP4 172.16.99.9 ˙t=0 0 ˙m=audio 17266 RTP/AVP 8 101 ˙c=IN IP4 172.16.99.9 ˙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 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 ...State changed from Null to Calling, event=TX_MSG [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ....Transaction tsx0x7f4b18035318 state changed to Calling [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is CALLING [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Sending request [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Method is INVITE [May 28 15:52:04] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) [May 28 15:52:04] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP response (404 bytes) from UDP:172.16.99.2:5060 ---> ˙SIP/2.0 100 Giving a try ˙Via: SIP/2.0/UDP 172.16.99.9:5060;received=172.16.99.9;rport=5060;branch=z9hG4bKPje62d7d90-484f-4833-8880-9f70bce2c04d ˙From: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙To: ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 2555 INVITE ˙Server: OpenSIPS (1.11.1-notls (x86_64/linux)) ˙Content-Length: 0 ˙ ˙ [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:04] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:04] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:04] DEBUG[4592] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current transaction state is Calling [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is CALLING [May 28 15:52:04] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=2555 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 .Incoming Response msg 100/INVITE/cseq=2555 (rdata0x7f4b0c009528) in state Calling [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 ..State changed from Calling to Proceeding, event=RX_MSG [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Received Response msg 100/INVITE/cseq=2555 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Transaction tsx0x7f4b18035318 state changed to Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current transaction state is Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction state change event is RX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is CALLING [May 28 15:52:04] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) [May 28 15:52:04] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP response (482 bytes) from UDP:172.16.99.2:5060 ---> ˙SIP/2.0 180 Ringing ˙To: ;tag=7d5833d5b327515bi0 ˙From: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 2555 INVITE ˙Via: SIP/2.0/UDP 172.16.99.9:5060;received=172.16.99.9;rport=5060;branch=z9hG4bKPje62d7d90-484f-4833-8880-9f70bce2c04d ˙Record-Route: ˙Server: Linksys/SPA921-5.1.8 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:04] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=2555 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 .Incoming Response msg 180/INVITE/cseq=2555 (rdata0x7f4b0c009528) in state Proceeding [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18035 ..State changed from Proceeding to Proceeding, event=RX_MSG [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Received Response msg 180/INVITE/cseq=2555 (rdata0x7f4b0c009528) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ....Route-set updated [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Transaction tsx0x7f4b18035318 state changed to Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is EARLY [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Received response [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Response is 180 Ringing [May 28 15:52:04] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current transaction state is Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction state change event is RX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is EARLY [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [May 28 15:52:04] DEBUG[4592] pjsip: inv0x7f4b18005 .Sending Response msg 180/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 ..Sending Response msg 180/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18016 ..Sending Response msg 180/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) in state Proceeding [May 28 15:52:04] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP response (695 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 180 Ringing ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bKf243.247a1fe2.0 ˙Via: SIP/2.0/UDP 172.16.99.1:5060;rport=5060;received=172.16.99.1;branch=z9hG4bK-o25843889533782139396156 ˙Record-Route: ˙Call-ID: 1401-252974-844422 ˙From: "9940077312" ;tag=843813252974 ˙To: ;tag=e7a57971-6093-4f53-8e42-2b62f4e88ccf ˙CSeq: 843806 INVITE ˙Server: Asterisk PBX 12 ˙Contact: ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER ˙Content-Length: 0 ˙ ˙ [May 28 15:52:04] DEBUG[4592] pjsip: tsx0x7f4b18016 ...State changed from Proceeding to Proceeding, event=TX_MSG [May 28 15:52:04] DEBUG[4592] pjsip: dlg0x7f4b18005 ....Transaction tsx0x7f4b180164a8 state changed to Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is EARLY [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Sending response [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current transaction state is Proceeding [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:04] DEBUG[4592] res_pjsip_session.c: The current inv state is EARLY [May 28 15:52:04] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:04] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] devicestate.c: Changing state for PJSIP/sip123456 - state 6 (Ringing) [May 28 15:52:04] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - opensips [May 28 15:52:04] DEBUG[4647] app_queue.c: Device 'PJSIP/sip123456' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 28 15:52:04] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:04] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'opensips' [May 28 15:52:04] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:04] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:04] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:04] DEBUG[4578] devicestate.c: Changing state for PJSIP/opensips - state 2 (In use) [May 28 15:52:04] DEBUG[4647] app_queue.c: Device 'PJSIP/opensips' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 28 15:52:07] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c009528) [May 28 15:52:07] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP response (861 bytes) from UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙To: ;tag=7d5833d5b327515bi0 ˙From: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 2555 INVITE ˙Via: SIP/2.0/UDP 172.16.99.9:5060;received=172.16.99.9;rport=5060;branch=z9hG4bKPje62d7d90-484f-4833-8880-9f70bce2c04d ˙Record-Route: ˙Contact: "sip123456" ˙Server: Linksys/SPA921-5.1.8 ˙Content-Length: 210 ˙Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER ˙Supported: replaces ˙Content-Type: application/sdp ˙ ˙v=0 ˙o=- 1001645 1001645 IN IP4 172.16.99.101 ˙s=- ˙c=IN IP4 172.16.99.101 ˙t=0 0 ˙m=audio 16436 RTP/AVP 8 101 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:101 telephone-event/8000 ˙a=fmtp:101 0-15 ˙a=ptime:30 ˙a=sendrecv ˙ [May 28 15:52:07] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) [May 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18035 .Incoming Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) in state Proceeding [May 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18035 ..State changed from Proceeding to Terminated, event=RX_MSG [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Received Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18015 ....Route-set updated [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18015 ....Route-set frozen [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18015 ...Transaction tsx0x7f4b18035318 state changed to Terminated [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONNECTING [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Received response [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Response is 200 OK [May 28 15:52:07] DEBUG[4592] pjsip: inv0x7f4b18015 ....Got SDP answer in Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c0021b8) [May 28 15:52:07] DEBUG[4592] pjsip: inv0x7f4b18015 ....SDP negotiation done, status=0 [May 28 15:52:07] DEBUG[4592] netsock2.c: Splitting '172.16.99.101' into... [May 28 15:52:07] DEBUG[4592] netsock2.c: ...host '172.16.99.101' and port ''. [May 28 15:52:07] DEBUG[4592] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4b1802a8c8' [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Setting payload 8 based on m type on 0x7f4b0050d790 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Setting payload 101 based on m type on 0x7f4b0050d790 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Copying payload 8 from 0x7f4b0050d790 to 0x7f4b1802aa08 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Copying payload 101 from 0x7f4b0050d790 to 0x7f4b1802aa08 [May 28 15:52:07] DEBUG[4592] pjsip: inv0x7f4b18015 ....Received Response msg 200/INVITE/cseq=2555 (rdata0x7f4b0c0021b8), sending ACK [May 28 15:52:07] DEBUG[4592] pjsip: endpoint ....Request msg ACK/cseq=2555 (tdta0x7f4b0c000c60) created. [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18015 .....Sending Request msg ACK/cseq=2555 (tdta0x7f4b0c000c60) [May 28 15:52:07] DEBUG[4592] pjsip: sip_resolve.c .....Target '172.16.99.2:0' type=Unspecified resolved to '172.16.99.2:5060' type=UDP (UDP transport) [May 28 15:52:07] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP request (489 bytes) to UDP:172.16.99.2:5060 ---> ˙ACK sip:sip123456@172.16.99.101:5064 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.9:5060;rport;branch=z9hG4bKPj4a0f9293-a1d3-4393-b93f-76ba35ccf429 ˙From: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙To: ;tag=7d5833d5b327515bi0 ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 2555 ACK ˙Route: ˙Max-Forwards: 70 ˙User-Agent: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b18035318) [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONFIRMED [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Sending request [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Method is ACK [May 28 15:52:07] DEBUG[4651][C-00000000] app.c: PJSIP/sip123456-00000001 Original location: 4232050001,sip123456,1 [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is 'start' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is 'sip123456' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG3' is '764af0f9-de3a-4997-9ca3-5d00c7cb87c9' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG4' is '9940077312' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG5' is '4232050001' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Launching 'Macro' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is 'CURL_RESULT' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is 'http://aster.voserver.net/radius.php?action=start&user=sip123456&uuid=764af0f9-de3a-4997-9ca3-5d00c7cb87c9&src=9940077312&dst=4232050001' [May 28 15:52:07] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - sip123456 [May 28 15:52:07] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:07] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:07] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:07] DEBUG[4592] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:07] DEBUG[4592] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:07] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4592] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:07] DEBUG[4592] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current transaction state is Terminated [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction state change event is RX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONFIRMED [May 28 15:52:07] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:07] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:07] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:07] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] devicestate.c: Changing state for PJSIP/sip123456 - state 2 (In use) [May 28 15:52:07] DEBUG[4647] app_queue.c: Device 'PJSIP/sip123456' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 28 15:52:07] DEBUG[4651][C-00000000] func_curl.c: Called with data=0x7f4ad0091310, str=0x7f4b1004e630, realsize=1, len=16, used=0 [May 28 15:52:07] DEBUG[4651][C-00000000] func_curl.c: Now, len=16, used=1 [May 28 15:52:07] DEBUG[4651][C-00000000] func_curl.c: str='1' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Function CURL(http://aster.voserver.net/radius.php?action=start&user=sip123456&uuid=764af0f9-de3a-4997-9ca3-5d00c7cb87c9&src=9940077312&dst=4232050001) result is '1' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:07] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:07] DEBUG[4651][C-00000000] app_macro.c: Executed application: Macro [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG6' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG7' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is 'start' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is 'sip123456' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG6' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG5' is '4232050001' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG7' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:07] DEBUG[4651][C-00000000] app_macro.c: Executed application: ExecIf [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG6' (from 'ARG6}" != ""' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG6' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG7' (from 'ARG7}" != ""' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG7' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG1' (from 'ARG1}&user=${ARG2}&uuid=${ARG6}&src=${ARG5}&dst=${ARG7})' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG1' is 'start' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG2' (from 'ARG2}&uuid=${ARG6}&src=${ARG5}&dst=${ARG7})' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG2' is 'sip123456' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG6' (from 'ARG6}&src=${ARG5}&dst=${ARG7})' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG6' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG5' (from 'ARG5}&dst=${ARG7})' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG5' is '4232050001' [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Evaluating 'ARG7' (from 'ARG7})' len 4) [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Result of 'ARG7' is NULL [May 28 15:52:07] DEBUG[4651][C-00000000] pbx.c: Launching 'MacroExit' [May 28 15:52:07] DEBUG[4651][C-00000000] app.c: Macro exited with status 0 [May 28 15:52:07] DEBUG[4651][C-00000000] app.c: PJSIP/sip123456-00000001 Ending location: 4232050001,sip123456,1 [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18035 Timeout timer event [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18035 .State changed from Terminated to Destroyed, event=TIMER [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18035 Transaction destroyed! [May 28 15:52:07] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - opensips [May 28 15:52:07] DEBUG[4651][C-00000000] features.c: Removing dialed interfaces datastore on PJSIP/sip123456-00000001 since we're bridging [May 28 15:52:07] DEBUG[4651][C-00000000] bridge_native_rtp.c: Bridge '9bc0b616-a438-4793-b943-b25a7b614b4d' can not use native RTP bridge as two channels are required [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: calling simple_bridge technology constructor [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: calling simple_bridge technology start [May 28 15:52:07] DEBUG[4592] pjsip: inv0x7f4b18005 .SDP negotiation done, status=0 [May 28 15:52:07] DEBUG[4592] netsock2.c: Splitting '172.16.99.1' into... [May 28 15:52:07] DEBUG[4592] netsock2.c: ...host '172.16.99.1' and port ''. [May 28 15:52:07] DEBUG[4592] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4b0c00b4a8' [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Setting payload 8 based on m type on 0x7f4b0050d9c0 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Setting payload 101 based on m type on 0x7f4b0050d9c0 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Copying payload 8 from 0x7f4b0050d9c0 to 0x7f4b0c00b5e8 [May 28 15:52:07] DEBUG[4592] rtp_engine.c: Copying payload 101 from 0x7f4b0050d9c0 to 0x7f4b0c00b5e8 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Method is INVITE, Response is 200 OK [May 28 15:52:07] DEBUG[4592] pjsip: inv0x7f4b18005 .Sending Response msg 200/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18005 ..Sending Response msg 200/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18016 ..Sending Response msg 200/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) in state Proceeding [May 28 15:52:07] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP response (1027 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bKf243.247a1fe2.0 ˙Via: SIP/2.0/UDP 172.16.99.1:5060;rport=5060;received=172.16.99.1;branch=z9hG4bK-o25843889533782139396156 ˙Record-Route: ˙Call-ID: 1401-252974-844422 ˙From: "9940077312" ;tag=843813252974 ˙To: ;tag=e7a57971-6093-4f53-8e42-2b62f4e88ccf ˙CSeq: 843806 INVITE ˙Server: Asterisk PBX 12 ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 1133 1135 IN IP4 localhost.localdomain ˙s=Asterisk ˙c=IN IP4 172.16.99.9 ˙t=0 0 ˙m=audio 18028 RTP/AVP 8 101 ˙c=IN IP4 172.16.99.9 ˙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 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18016 ...State changed from Proceeding to Completed, event=TX_MSG [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18005 ....Transaction tsx0x7f4b180164a8 state changed to Completed [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONNECTING [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is TX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Sending response [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Method is INVITE, Response is 200 OK [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f4b180164a8) [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current transaction state is Completed [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONNECTING [May 28 15:52:07] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:07] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'opensips' [May 28 15:52:07] DEBUG[4651][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b1000a148(PJSIP/opensips-00000000) is joining [May 28 15:52:07] DEBUG[4651][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: pushing 0x7f4b1000a148(PJSIP/opensips-00000000) [May 28 15:52:07] DEBUG[4651][C-00000000] bridge_native_rtp.c: Bridge '9bc0b616-a438-4793-b943-b25a7b614b4d' can not use native RTP bridge as two channels are required [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is already using the new technology. [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is happy that channel PJSIP/opensips-00000000 already has read format alaw [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is happy that channel PJSIP/opensips-00000000 already has write format alaw [May 28 15:52:07] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b1000a148(PJSIP/opensips-00000000) is joining simple_bridge technology [May 28 15:52:07] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:07] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:07] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:07] DEBUG[4578] devicestate.c: Changing state for PJSIP/opensips - state 2 (In use) [May 28 15:52:07] DEBUG[4654][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b10009d38(PJSIP/sip123456-00000001) is joining [May 28 15:52:07] DEBUG[4654][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: pushing 0x7f4b10009d38(PJSIP/sip123456-00000001) [May 28 15:52:07] DEBUG[4581] cdr.c: Finalized CDR for PJSIP/sip123456-00000001 - start 1401252724.161874 answer 1401252727.470466 end 1401252727.483649 dispo ANSWERED [May 28 15:52:07] DEBUG[4654][C-00000000] bridge_native_rtp.c: Bridge '9bc0b616-a438-4793-b943-b25a7b614b4d' can not use native RTP bridge as channel 'PJSIP/sip123456-00000001' has DTMF hooks [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is already using the new technology. [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is happy that channel PJSIP/sip123456-00000001 already has read format alaw [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is happy that channel PJSIP/sip123456-00000001 already has write format alaw [May 28 15:52:07] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b10009d38(PJSIP/sip123456-00000001) is joining simple_bridge technology [May 28 15:52:07] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=843806 (rdata0x7f4b0c009528) [May 28 15:52:07] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (636 bytes) from UDP:172.16.99.2:5060 ---> ˙ACK sip:172.16.99.9:5060 SIP/2.0 ˙Record-Route: ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bKf243.247a1fe2.2 ˙Via: SIP/2.0/UDP 172.16.99.1:5060;received=172.16.99.1;rport=5060;branch=z9hG4bK-o25843889533799318694896 ˙From: "9940077312" ;tag=843813252974 ˙To: ;tag=e7a57971-6093-4f53-8e42-2b62f4e88ccf ˙Call-ID: 1401-252974-844422 ˙CSeq: 843806 ACK ˙User-Agent: Eltex smg_pa_sip 2.15.1.32 ˙Max-Forwards: 69 ˙Contact: ˙P-Eltex-Info: {trunk,2} 1133 <0.24279.4> ˙Content-Length: 0 ˙ ˙ [May 28 15:52:07] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=843806 (rdata0x7f4b0c0021b8) [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18005 .Received Request msg ACK/cseq=843806 (rdata0x7f4b0c0021b8) [May 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18016 ..Request to terminate transaction [May 28 15:52:07] DEBUG[4592] pjsip: tsx0x7f4b18016 ...State changed from Completed to Terminated, event=USER [May 28 15:52:07] DEBUG[4592] pjsip: dlg0x7f4b18005 ....Transaction tsx0x7f4b180164a8 state changed to Terminated [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current transaction state is Terminated [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The transaction state change event is USER [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONNECTING [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: The current inv state is CONFIRMED [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Received request [May 28 15:52:07] DEBUG[4592] res_pjsip_session.c: Method is ACK [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18016 Timeout timer event [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18016 .State changed from Terminated to Destroyed, event=TIMER [May 28 15:52:07] DEBUG[4597] pjsip: tdta0x7f4b0c00 ..Destroying txdata Response msg 200/INVITE/cseq=843806 (tdta0x7f4b0c0084f0) [May 28 15:52:07] DEBUG[4597] pjsip: tsx0x7f4b18016 Transaction destroyed! [May 28 15:52:07] DEBUG[4654][C-00000000] res_rtp_asterisk.c: 0x7f4b1802ee10 -- Probation learning mode pass with source address 172.16.99.101:16436 [May 28 15:52:07] DEBUG[4651][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [May 28 15:52:07] DEBUG[4651][C-00000000] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [May 28 15:52:07] DEBUG[4651][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f4b0c00b4a8' [May 28 15:52:07] DEBUG[4651][C-00000000] res_rtp_asterisk.c: 0x7f4b0c0106d0 -- Probation learning mode pass with source address 172.16.99.1:54202 [May 28 15:52:07] DEBUG[4654][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [May 28 15:52:07] DEBUG[4654][C-00000000] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [May 28 15:52:14] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=101 (rdata0x7f4b0c009528) [May 28 15:52:14] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (538 bytes) from UDP:172.16.99.2:5060 ---> ˙BYE sip:ec9e742d-a6e3-4d48-991c-9f7a1f6dd4db@172.16.99.9:5060 SIP/2.0 ˙Record-Route: ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bKea83.e7c73a72.0 ˙Via: SIP/2.0/UDP 172.16.99.101:5064;branch=z9hG4bK-6c0fa95e ˙From: ;tag=7d5833d5b327515bi0 ˙To: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙CSeq: 101 BYE ˙Max-Forwards: 69 ˙User-Agent: Linksys/SPA921-5.1.8 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:14] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=101 (rdata0x7f4b0c0021b8) [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 .Received Request msg BYE/cseq=101 (rdata0x7f4b0c0021b8) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18016 ...Transaction created for Request msg BYE/cseq=101 (rdata0x7f4b0c0021b8) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18016 ..Incoming Request msg BYE/cseq=101 (rdata0x7f4b0c0021b8) in state Null [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18016 ...State changed from Null to Trying, event=RX_MSG [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 ....Transaction tsx0x7f4b180164a8 state changed to Trying [May 28 15:52:14] DEBUG[4592] pjsip: endpoint .....Response msg 200/BYE/cseq=101 (tdta0x7f4b180098c0) created [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 ......Sending Response msg 200/BYE/cseq=101 (tdta0x7f4b180098c0) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18016 ......Sending Response msg 200/BYE/cseq=101 (tdta0x7f4b180098c0) in state Trying [May 28 15:52:14] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP response (484 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bKea83.e7c73a72.0 ˙Via: SIP/2.0/UDP 172.16.99.101:5064;branch=z9hG4bK-6c0fa95e ˙Record-Route: ˙Call-ID: b752b222-eaa4-4ea4-ac4b-348b9ceca432 ˙From: ;tag=7d5833d5b327515bi0 ˙To: "9940077312" ;tag=76acd9ce-4c72-49c3-a04c-19abaf70d0bd ˙CSeq: 101 BYE ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18016 .......State changed from Trying to Completed, event=TX_MSG [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 ........Transaction tsx0x7f4b180164a8 state changed to Completed [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current transaction state is Completed [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is CONFIRMED [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with sip123456 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is DISCONNCTD [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Received request [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Method is BYE [May 28 15:52:14] DEBUG[4592] pjsip: tdta0x7f4b0c00 .....Destroying txdata Request msg ACK/cseq=2555 (tdta0x7f4b0c000c60) [May 28 15:52:14] DEBUG[4592] pjsip: tdta0x7f4b1800 .....Destroying txdata Request msg INVITE/cseq=2555 (tdta0x7f4b18004190) [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 ......Session count dec to 4 by mod-invite [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: inv_session 0x7f4b180145f8 has no ast session [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b180164a8 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current transaction state is Completed [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction state change event is RX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is DISCONNCTD [May 28 15:52:14] DEBUG[4654][C-00000000] bridge_channel.c: Setting 0x7f4b10009d38(PJSIP/sip123456-00000001) state from:0 to:1 [May 28 15:52:14] DEBUG[4654][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: pulling 0x7f4b10009d38(PJSIP/sip123456-00000001) [May 28 15:52:14] DEBUG[4654][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b10009d38(PJSIP/sip123456-00000001) is leaving simple_bridge technology [May 28 15:52:14] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: dissolving bridge with cause 16(Normal Clearing) [May 28 15:52:14] DEBUG[4654][C-00000000] bridge_channel.c: Setting 0x7f4b1000a148(PJSIP/opensips-00000000) state from:0 to:2 [May 28 15:52:14] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: queueing action type:13 sub:1001 [May 28 15:52:14] DEBUG[4581] cdr.c: Finalized CDR for PJSIP/opensips-00000000 - start 1401252724.080225 answer 1401252727.480528 end 1401252734.768356 dispo ANSWERED [May 28 15:52:14] DEBUG[4654][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is dissolved, not performing smart bridge operation. [May 28 15:52:14] DEBUG[4654][C-00000000] channel.c: Hanging up channel 'PJSIP/sip123456-00000001' [May 28 15:52:14] DEBUG[4654][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Destroying SIP session with endpoint sip123456 [May 28 15:52:14] DEBUG[4592] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4b1802a8c8' [May 28 15:52:14] DEBUG[4592] rtp_engine.c: Destroyed RTP instance '0x7f4b1802a8c8' [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18015 .Session count dec to 0 by Session Module [May 28 15:52:14] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - sip123456 [May 28 15:52:14] DEBUG[4592] taskprocessor.c: destroying taskprocessor 'eb488b89-1545-41bd-b4df-850307629e58' [May 28 15:52:14] DEBUG[4581] cdr.c: CDR for PJSIP/sip123456-00000001 is dialed and has no Party B; discarding [May 28 15:52:14] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:14] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'sip123456' [May 28 15:52:14] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:14] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] devicestate.c: Changing state for PJSIP/sip123456 - state 1 (Not in use) [May 28 15:52:14] DEBUG[4647] app_queue.c: Device 'PJSIP/sip123456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 28 15:52:14] DEBUG[4651][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: pulling 0x7f4b1000a148(PJSIP/opensips-00000000) [May 28 15:52:14] DEBUG[4651][C-00000000] bridge_channel.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: 0x7f4b1000a148(PJSIP/opensips-00000000) is leaving simple_bridge technology [May 28 15:52:14] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d is dissolved, not performing smart bridge operation. [May 28 15:52:14] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: actually destroying basic bridge, nobody wants it anymore [May 28 15:52:14] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: calling basic bridge destructor [May 28 15:52:14] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: calling simple_bridge technology stop [May 28 15:52:14] DEBUG[4651][C-00000000] bridge.c: Bridge 9bc0b616-a438-4793-b943-b25a7b614b4d: calling simple_bridge technology destructor [May 28 15:52:14] DEBUG[4651][C-00000000] app_dial.c: Exiting with DIALSTATUS=ANSWER. [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_CF_TARGET' is '9940077312' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UUID' is '764af0f9-de3a-4997-9ca3-5d00c7cb87c9' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_SRC' is '9940077312' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'REDIRECTED_UUID' is NULL [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_CF_TARGET' is '9940077312' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'CF_TYPE' is 'unavailable' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '1' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_CF_TARGET' is '9940077312' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'USER' is 'sip123456' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UUID' is '764af0f9-de3a-4997-9ca3-5d00c7cb87c9' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_SRC' is '9940077312' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'UTM5_DST' is '4232050001' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'REDIRECTED_UUID' is NULL [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ExecIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Hangup' [May 28 15:52:14] DEBUG[4651][C-00000000] channel.c: Soft-Hanging up channel 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Spawn extension (4232050001,sip123456,21) exited non-zero on 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] channel.c: Soft-Hanging up channel 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] channel.c: Soft-Hanging up channel 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Macro' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'ResetCDR' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: ResetCDR [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'NoCDR' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: NoCDR [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Set' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: Set [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HC' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'DS' is 'ANSWER' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'NoOp' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: NoOp [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HC' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Expression result is '0' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'GotoIf' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Not taking any branch [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: GotoIf [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HC' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Goto' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: Goto [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HC' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'NoOp' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: NoOp [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Goto' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Executed application: Goto [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Result of 'HC' is '16' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Launching 'Hangup' [May 28 15:52:14] DEBUG[4651][C-00000000] channel.c: Soft-Hanging up channel 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] app_macro.c: Spawn extension (macro-handle_hangup,ind-hangup,1) exited non-zero on 'PJSIP/opensips-00000000' in macro 'handle_hangup' [May 28 15:52:14] DEBUG[4651][C-00000000] pbx.c: Spawn extension (4232050001,h,1) exited non-zero on 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] channel.c: Hanging up channel 'PJSIP/opensips-00000000' [May 28 15:52:14] DEBUG[4651][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [May 28 15:52:14] DEBUG[4592] pjsip: endpoint .Request msg BYE/cseq=2617 (tdta0x7f4b0c0084f0) created. [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Method is BYE [May 28 15:52:14] DEBUG[4592] pjsip: inv0x7f4b18005 .Sending Request msg BYE/cseq=2617 (tdta0x7f4b0c0084f0) [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 ..Sending Request msg BYE/cseq=2617 (tdta0x7f4b0c0084f0) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18035 ...Transaction created for Request msg BYE/cseq=2616 (tdta0x7f4b0c0084f0) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18035 ..Sending Request msg BYE/cseq=2616 (tdta0x7f4b0c0084f0) in state Null [May 28 15:52:14] DEBUG[4592] pjsip: sip_resolve.c ...Target '172.16.99.2:0' type=Unspecified resolved to '172.16.99.2:5060' type=UDP (UDP transport) [May 28 15:52:14] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP request (504 bytes) to UDP:172.16.99.2:5060 ---> ˙BYE sip:9940077312@172.16.99.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.9:5060;rport;branch=z9hG4bKPj18a74bed-2fe7-491d-a217-65983a8802ba ˙From: ;tag=e7a57971-6093-4f53-8e42-2b62f4e88ccf ˙To: "9940077312" ;tag=843813252974 ˙Call-ID: 1401-252974-844422 ˙CSeq: 2616 BYE ˙Route: ˙Reason: Q.850;cause=16 ˙Max-Forwards: 70 ˙User-Agent: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18035 ...State changed from Null to Calling, event=TX_MSG [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 ....Transaction tsx0x7f4b18035318 state changed to Calling [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current transaction state is Calling [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction state change event is TX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is CONFIRMED [May 28 15:52:14] DEBUG[4581] cdr.c: Finalized CDR for PJSIP/opensips-00000000 - start 1401252734.782232 answer 1401252734.782233 end 1401252734.788006 dispo ANSWERED [May 28 15:52:14] DEBUG[4581] cdr.c: Finalized CDR for PJSIP/opensips-00000000 - start 1401252734.782233 answer 1401252734.782233 end 1401252734.788016 dispo ANSWERED [May 28 15:52:14] DEBUG[4581] cdr_mysql.c: Inserting a CDR record. [May 28 15:52:14] DEBUG[4581] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`channel`,`dstchannel`,`amaflags`,`uniqueid`,`answer`,`end`) VALUES ('2014-05-28 15:52:14','\"9940077312\" <9940077312>','9940077312','sip123456','4232050001','Dial','PJSIP/sip123456,60,gtM(utm5^start^sip123456^764af0f9-de3a-4997-9ca3-5d00c7cb87c','0.005774','0.005773','ANSWERED','PJSIP/opensips-00000000','PJSIP/sip123456-00000001','DOCUMENTATION','1401252724.0','2014-05-28 15:52:14','2014-05-28 15:52:14') [May 28 15:52:14] DEBUG[4578] devicestate.c: No provider found, checking channel drivers for PJSIP - opensips [May 28 15:52:14] DEBUG[4578] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:14] DEBUG[4578] res_config_odbc.c: Parameter 1 ('id') = 'opensips' [May 28 15:52:14] DEBUG[4578] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:14] DEBUG[4578] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:14] DEBUG[4578] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:14] DEBUG[4578] devicestate.c: Changing state for PJSIP/opensips - state 1 (Not in use) [May 28 15:52:14] DEBUG[4647] app_queue.c: Device 'PJSIP/opensips' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 28 15:52:14] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=2616 (rdata0x7f4b0c009528) [May 28 15:52:14] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP response (612 bytes) from UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 172.16.99.9:5060;received=172.16.99.9;rport=5060;branch=z9hG4bKPj18a74bed-2fe7-491d-a217-65983a8802ba ˙Record-Route: ˙From: ;tag=e7a57971-6093-4f53-8e42-2b62f4e88ccf ˙To: "9940077312" ;tag=843813252974 ˙Call-ID: 1401-252974-844422 ˙CSeq: 2616 BYE ˙Accept: multipart/mixed, application/sdp ˙Contact: ˙P-Eltex-Info: {trunk,2} 1133 <0.24279.4> ˙User-Agent: Eltex smg_pa_sip 2.15.1.32 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:14] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=2616 (rdata0x7f4b0c024e78) [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18035 .Incoming Response msg 200/BYE/cseq=2616 (rdata0x7f4b0c024e78) in state Calling [May 28 15:52:14] DEBUG[4592] pjsip: tsx0x7f4b18035 ..State changed from Calling to Completed, event=RX_MSG [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 ...Received Response msg 200/BYE/cseq=2616 (rdata0x7f4b0c024e78) [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 ...Transaction tsx0x7f4b18035318 state changed to Completed [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The state change pertains to the session with opensips [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: There is no transaction involved in this state change [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is DISCONNCTD [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Source of transaction state change is RX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Received response [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Response is 200 OK [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Destroying SIP session with endpoint opensips [May 28 15:52:14] DEBUG[4592] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4b0c00b4a8' [May 28 15:52:14] DEBUG[4592] rtp_engine.c: Destroyed RTP instance '0x7f4b0c00b4a8' [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 .....Session count dec to 2 by Session Module [May 28 15:52:14] DEBUG[4592] pjsip: dlg0x7f4b18005 .....Session count dec to 1 by mod-invite [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: inv_session 0x7f4b18018dd8 has no ast session [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current transaction state is Completed [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The transaction state change event is RX_MSG [May 28 15:52:14] DEBUG[4592] res_pjsip_session.c: The current inv state is DISCONNCTD [May 28 15:52:14] DEBUG[4592] taskprocessor.c: destroying taskprocessor 'a8deed2d-6259-476b-b605-b281a63e1a16' [May 28 15:52:17] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=10 (rdata0x7f4b0c024e78) [May 28 15:52:17] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (360 bytes) from UDP:172.16.99.2:5060 ---> ˙OPTIONS sip:172.16.99.9:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bK073.595e1774.0 ˙To: sip:172.16.99.9:5060 ˙From: ;tag=28892ca7cba2b104f2577d65fc0fc8bd-cffc ˙CSeq: 10 OPTIONS ˙Call-ID: 4c2d860e28418b6c-2287@172.16.99.2 ˙Max-Forwards: 70 ˙Content-Length: 0 ˙User-Agent: OpenSIPS (1.11.1-notls (x86_64/linux)) ˙ ˙ [May 28 15:52:17] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=10 (rdata0x7f4b0c0021b8) [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'pinger@172.16.99.2' [May 28 15:52:17] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'pinger' [May 28 15:52:17] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:17] DEBUG[4592] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username 'pinger' [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [May 28 15:52:17] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:17] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:17] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:17] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:17] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:17] DEBUG[4592] acl.c: 172.16.99.2:0/255.255.255.255:0 sense 0 appended to ACL [May 28 15:52:17] DEBUG[4592] netsock2.c: Splitting '172.16.99.2' into... [May 28 15:52:17] DEBUG[4592] netsock2.c: ...host '172.16.99.2' and port ''. [May 28 15:52:17] DEBUG[4592] res_pjsip_endpoint_identifier_ip.c: Source address 172.16.99.2:5060 matches identify 'opensips' [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:17] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'opensips' [May 28 15:52:17] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:17] DEBUG[4592] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:17] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:17] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:17] DEBUG[4592] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint opensips [May 28 15:52:17] DEBUG[4592] pjsip: endpoint .Response msg 404/OPTIONS/cseq=10 (tdta0x7f4b0c000c60) created [May 28 15:52:17] VERBOSE[4592] res_pjsip_logger.c: <--- Transmitting SIP response (775 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 404 Not Found ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bK073.595e1774.0 ˙Call-ID: 4c2d860e28418b6c-2287@172.16.99.2 ˙From: ;tag=28892ca7cba2b104f2577d65fc0fc8bd-cffc ˙To: ;tag=z9hG4bK073.595e1774.0 ˙CSeq: 10 OPTIONS ˙Accept: application/sdp, application/pidf+xml, application/simple-message-summary, application/pidf+xml, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, message/sipfrag;version=2.0 ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER ˙Supported: 100rel, timer, replaces, norefersub ˙Accept-Encoding: text/plain ˙Accept-Language: en ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:17] DEBUG[4592] pjsip: tdta0x7f4b0c00 .Destroying txdata Response msg 404/OPTIONS/cseq=10 (tdta0x7f4b0c000c60) [May 28 15:52:18] DEBUG[4597] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=46978 (rdata0x7f4b0c024e78) [May 28 15:52:18] VERBOSE[4597] res_pjsip_logger.c: <--- Received SIP request (638 bytes) from UDP:172.16.99.2:5060 ---> ˙REGISTER sip:172.16.99.9:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 172.16.99.2:5060;branch=z9hG4bK09ff.5e7729e.0 ˙Via: SIP/2.0/UDP 172.16.99.241:5065;received=172.16.99.241;rport=5065;branch=z9hG4bKPjfe5c9f17-d64d-4c66-b750-16ce29bc04cf ˙Max-Forwards: 69 ˙From: ;tag=9a86170d-ef1b-41de-98a2-ce62a373c596 ˙To: ˙Call-ID: 59d57706-dd30-49f2-b687-b304e212c797 ˙CSeq: 46978 REGISTER ˙User-Agent: SFLphone/1.3.0 ˙Contact: ˙Expires: 60 ˙Allow: PRACK, SUBSCRIBE, NOTIFY, REFER, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, OPTIONS, MESSAGE, PUBLISH ˙Content-Length: 0 ˙ ˙ [May 28 15:52:18] DEBUG[4592] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=46978 (rdata0x7f4b0c0021b8) [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip000005@172.16.99.2' [May 28 15:52:18] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_endpoints WHERE id = ? [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip000005' [May 28 15:52:18] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:18] DEBUG[4592] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [1800] in [-2147483648, 2147483647] gives [1800](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [90] in [-2147483648, 2147483647] gives [90](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint sip000005 [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:18] DEBUG[4592] res_config_odbc.c: Parameter 1 ('id') = 'sip000005' [May 28 15:52:18] DEBUG[4592] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:18] DEBUG[4592] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [0] in [0, 86400] gives [0](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [0] in [0, 86400] gives [0](0) [May 28 15:52:18] DEBUG[4593] res_pjsip_registrar.c: Refreshed contact 'sip:sip000005@172.16.99.241:5065' on AOR 'sip000005' with new expiration of 60 seconds [May 28 15:52:18] DEBUG[4593] config.c: extract int from [0] in [0, 86400] gives [0](0) [May 28 15:52:18] DEBUG[4593] pjsip: endpoint Response msg 200/REGISTER/cseq=46978 (tdta0x7f4b0c00f720) created [May 28 15:52:18] DEBUG[4593] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM view_ps_aors WHERE id = ? [May 28 15:52:18] DEBUG[4593] res_config_odbc.c: Parameter 1 ('id') = 'sip000005' [May 28 15:52:18] DEBUG[4593] res_odbc.c: odbc_release_obj2(0x1c473b8) called (obj->txf = (nil)) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [60] in [-2147483648, 2147483647] gives [60](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [3600] in [-2147483648, 2147483647] gives [3600](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [7200] in [-2147483648, 2147483647] gives [7200](0) [May 28 15:52:18] DEBUG[4593] config.c: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [May 28 15:52:18] VERBOSE[4593] res_pjsip_logger.c: <--- Transmitting SIP response (618 bytes) to UDP:172.16.99.2:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 172.16.99.2:5060;rport;received=172.16.99.2;branch=z9hG4bK09ff.5e7729e.0 ˙Via: SIP/2.0/UDP 172.16.99.241:5065;rport=5065;received=172.16.99.241;branch=z9hG4bKPjfe5c9f17-d64d-4c66-b750-16ce29bc04cf ˙Call-ID: 59d57706-dd30-49f2-b687-b304e212c797 ˙From: ;tag=9a86170d-ef1b-41de-98a2-ce62a373c596 ˙To: ;tag=z9hG4bK09ff.5e7729e.0 ˙CSeq: 46978 REGISTER ˙Date: Wed, 28 May 2014 04:52:18 GMT ˙Contact: ;expires=59 ˙Contact: ˙Server: Asterisk PBX 12 ˙Content-Length: 0 ˙ ˙ [May 28 15:52:18] DEBUG[4593] pjsip: tdta0x7f4b0c00 Destroying txdata Response msg 200/REGISTER/cseq=46978 (tdta0x7f4b0c00f720) [May 28 15:52:19] DEBUG[4597] pjsip: tsx0x7f4b18035 Timeout timer event [May 28 15:52:19] DEBUG[4597] pjsip: tsx0x7f4b18035 .State changed from Completed to Terminated, event=TIMER [May 28 15:52:19] DEBUG[4597] pjsip: dlg0x7f4b18005 ..Transaction tsx0x7f4b18035318 state changed to Terminated [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: inv_session 0x7f4b18018dd8 has no ast session [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: The inv session does NOT have an invite_tsx [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: The transaction involved in this state change is 0x7f4b18035318 [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: The current transaction state is Terminated [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: The transaction state change event is TIMER [May 28 15:52:19] DEBUG[4597] res_pjsip_session.c: The current inv state is DISCONNCTD [May 28 15:52:19] DEBUG[4597] pjsip: dlg0x7f4b18005 ...Dialog destroyed [May 28 15:52:19] DEBUG[4597] pjsip: tsx0x7f4b18035 Timeout timer event [May 28 15:52:19] DEBUG[4597] pjsip: tsx0x7f4b18035 .State changed from Terminated to Destroyed, event=TIMER [May 28 15:52:19] DEBUG[4597] pjsip: tdta0x7f4b0c00 ..Destroying txdata Request msg BYE/cseq=2616 (tdta0x7f4b0c0084f0) [May 28 15:52:19] DEBUG[4597] pjsip: tsx0x7f4b18035 Transaction destroyed! [May 28 15:52:23] DEBUG[4570] cdr.c: CDR Engine termination request received; waiting on messages... [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [May 28 15:52:23] VERBOSE[4570] asterisk.c: Asterisk cleanly ending (0). [May 28 15:52:23] VERBOSE[4570] asterisk.c: Executing last minute cleanups [May 28 15:52:23] DEBUG[4570] res_musiconhold.c: Destroying MOH class 'default' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'ae2c4896-b54a-4e75-abde-a9524563a10f' [May 28 15:52:23] DEBUG[4570] logger.c: Unregistered dynamic logger level 'CC' with index 16. [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'CCSS core' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor '040936a6-8d1f-4c9f-9661-ac317632518a' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'a15754f3-460e-4996-839f-70b2351692d7' [May 28 15:52:23] DEBUG[4570] tcptls.c: Stopped server :: AMI server [May 28 15:52:23] DEBUG[4570] tcptls.c: Stopped server :: AMI TLS server [May 28 15:52:23] DEBUG[4570] channel.c: Unregistering channel type 'Local' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor '03ba855e-21e1-4c76-813d-793f09fe799b' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'b0c11a1b-8e5f-4400-857d-a62121f93484' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor '3defd4d8-adf8-4d67-927e-bde17fff2da3' [May 28 15:52:23] DEBUG[4570] tcptls.c: Stopped server :: http server [May 28 15:52:23] DEBUG[4570] bridge.c: Waiting for bridge manager thread to die. [May 28 15:52:23] DEBUG[4570] channel.c: Unregistering channel type 'Surrogate' [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [May 28 15:52:23] DEBUG[4570] threadpool.c: Destroying worker thread 5 [May 28 15:52:23] DEBUG[4570] taskprocessor.c: destroying taskprocessor 'Sorcery' [May 28 15:52:23] DEBUG[4570] asterisk.c: Asterisk ending (0).