[2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. <--- Received SIP request (834 bytes) from UDP:1.1.1.1:5060 ---> INVITE sip:84123456789@2.2.2.2 SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK5dc060917896b555 From: ;tag=257f258c53f1cdb5 To: User-Agent: VOS2009 V2.1.2.0 CSeq: 1 INVITE Call-ID: 6c78527a18178ee7c20b1f7b003c3912@1.1.1.1 Contact: Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, UPDATE, PRACK Supported: timer Session-Expires: 600;refresher=uas Content-Length: 284 Content-Type: application/sdp v=0 o=- 1681199333 1681199333 IN IP4 1.1.1.1 s=VOS2009 c=IN IP4 1.1.1.1 t=0 0 m=audio 10042 RTP/AVP 8 0 18 4 116 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:116 telephone-event/8000 a=fmtp:116 0-16 a=sendrecv [2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5060' into... [2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5060'. [2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '5.5.5.5:5060' into... [2023-04-11 14:53:42] DEBUG[28090]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '5.5.5.5' and port '5060'. [2023-04-11 14:53:42] DEBUG[28090]: res_pjsip/pjsip_distributor.c:394 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7fe934022fb8) [2023-04-11 14:53:42] DEBUG[28090]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=1 (rdata0x7fe934022fb8) [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('id LIKE') = '%' [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:42] DEBUG[24372]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:42] DEBUG[24372]: acl.c:570 debug_ha_sense_appended: 1.1.1.1:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000530' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000530-1' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000540' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000540-1' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000630' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000630-1' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000640' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000640-1' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:255 ip_identify_match_check: Source address 1.1.1.1:5060 matches identify '0123456789' [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('id') = '0123456789' [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:42] DEBUG[24372]: res_sorcery_realtime.c:132 sorcery_realtime_filter_objectset: Filtering out realtime field 'disallow' from retrieval [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [1] in [0, 4294967295] gives [1](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [1] in [0, 4294967295] gives [1](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [90] in [0, 4294967295] gives [90](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [900] in [0, 4294967295] gives [900](0) [2023-04-11 14:53:42] DEBUG[24372]: config.c:3845 ast_parse_arg: extract uint from [30] in [0, 4294967295] gives [30](0) [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_endpoint_identifier_ip.c:288 common_identify: Identify '0123456789' SIP message matched to endpoint 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4274 session_on_rx_request: (null session) Request: INVITE [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4100 handle_new_invite_request: Request: [2023-04-11 14:53:42] DEBUG[24372]: dsp.c:510 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2023-04-11 14:53:42] DEBUG[24372]: dsp.c:510 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=1 (rdata0x7fe934036118) [2023-04-11 14:53:42] DEBUG[24372]: chan_pjsip.c:2887 chan_pjsip_session_begin: 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: chan_pjsip.c:2891 chan_pjsip_session_begin: Direct media no glare mitigation [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:3954 new_invite: 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM extensions WHERE exten = ? AND priority = ? AND context = ? [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('exten') = '84123456789' [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:134 custom_prepare: Parameter 2 ('priority') = '1' [2023-04-11 14:53:42] DEBUG[24372]: res_config_odbc.c:134 custom_prepare: Parameter 3 ('context') = 'default' [2023-04-11 14:53:42] DEBUG[24372]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4038 new_invite: 0123456789: Call (UDP:1.1.1.1:5060) to extension '84123456789' sending 100 Trying [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4681 session_inv_on_state_changed: 0123456789 Event: TSX_STATE Inv State: DISCONNCTD [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4418 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4432 __print_debug_details: The state change pertains to the endpoint '0123456789()' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4437 __print_debug_details: The inv session still has an invite_tsx (0x7fe89403ea58) [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4452 __print_debug_details: There is no transaction involved in this state change [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4454 __print_debug_details: The current inv state is DISCONNCTD [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4707 session_inv_on_state_changed: 0123456789: Source of transaction state change is USER [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4754 session_inv_on_state_changed: [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4799 session_inv_on_tsx_state_changed: 0123456789 TSX State: Terminated Inv State: DISCONNCTD [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4418 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4432 __print_debug_details: The state change pertains to the endpoint '0123456789()' [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4440 __print_debug_details: The inv session does NOT have an invite_tsx [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4443 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fe89403ea58 [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4447 __print_debug_details: The current transaction state is Terminated [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4449 __print_debug_details: The transaction state change event is USER [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4454 __print_debug_details: The current inv state is DISCONNCTD [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4820 session_inv_on_tsx_state_changed: Disconnected [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4219 session_on_tsx_state: (null session) TSX State: Terminated Inv State: DISCONNCTD [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4227 session_on_tsx_state: [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4083 new_invite: 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4174 handle_new_invite_request: Request: Session: 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:4294 session_on_rx_request: (null session) Handled request INVITE ? yes [2023-04-11 14:53:42] DEBUG[24372]: chan_pjsip.c:2908 chan_pjsip_session_end: 0123456789 [2023-04-11 14:53:42] DEBUG[24372]: chan_pjsip.c:2911 chan_pjsip_session_end: No channel [2023-04-11 14:53:42] DEBUG[24372]: res_pjsip_session.c:2912 session_destructor: 0123456789: Destroying SIP session <--- Received SIP request (834 bytes) from UDP:1.1.1.1:5060 ---> INVITE sip:84123456789@2.2.2.2 SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK5dc060917896b555 From: ;tag=257f258c53f1cdb5 To: User-Agent: VOS2009 V2.1.2.0 CSeq: 1 INVITE Call-ID: 6c78527a18178ee7c20b1f7b003c3912@1.1.1.1 Contact: Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, UPDATE, PRACK Supported: timer Session-Expires: 600;refresher=uas Content-Length: 284 Content-Type: application/sdp v=0 o=- 1681199333 1681199333 IN IP4 1.1.1.1 s=VOS2009 c=IN IP4 1.1.1.1 t=0 0 m=audio 10042 RTP/AVP 8 0 18 4 116 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:116 telephone-event/8000 a=fmtp:116 0-16 a=sendrecv [2023-04-11 14:53:45] DEBUG[28090]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5060' into... [2023-04-11 14:53:45] DEBUG[28090]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5060'. [2023-04-11 14:53:45] DEBUG[28090]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '5.5.5.5:5060' into... [2023-04-11 14:53:45] DEBUG[28090]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '5.5.5.5' and port '5060'. [2023-04-11 14:53:45] DEBUG[28090]: res_pjsip/pjsip_distributor.c:394 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7fe934022fb8) [2023-04-11 14:53:45] DEBUG[28090]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=1 (rdata0x7fe934022fb8) [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('id LIKE') = '%' [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '3.3.3.3' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '3.3.3.3' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 3.3.3.3:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '4.4.4.4' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '4.4.4.4' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 4.4.4.4:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '1.1.1.1' into... [2023-04-11 14:53:45] DEBUG[28441]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port ''. [2023-04-11 14:53:45] DEBUG[28441]: acl.c:570 debug_ha_sense_appended: 1.1.1.1:0/255.255.255.255:0 sense 0 appended to ACL [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000530' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000530-1' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000540' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000540-1' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000630' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000630-1' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000640' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:260 ip_identify_match_check: Source address 1.1.1.1:5060 does not match identify '02400000640-1' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:255 ip_identify_match_check: Source address 1.1.1.1:5060 matches identify '0123456789' [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('id') = '0123456789' [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:45] DEBUG[28441]: res_sorcery_realtime.c:132 sorcery_realtime_filter_objectset: Filtering out realtime field 'disallow' from retrieval [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [1800] in [0, 4294967295] gives [1800](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [1] in [0, 4294967295] gives [1](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [1] in [0, 4294967295] gives [1](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [90] in [0, 4294967295] gives [90](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [900] in [0, 4294967295] gives [900](0) [2023-04-11 14:53:45] DEBUG[28441]: config.c:3845 ast_parse_arg: extract uint from [30] in [0, 4294967295] gives [30](0) [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_endpoint_identifier_ip.c:288 common_identify: Identify '0123456789' SIP message matched to endpoint 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4274 session_on_rx_request: (null session) Request: INVITE [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4100 handle_new_invite_request: Request: [2023-04-11 14:53:45] DEBUG[28441]: dsp.c:510 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2023-04-11 14:53:45] DEBUG[28441]: dsp.c:510 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip/pjsip_distributor.c:472 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000032 to use for Request msg INVITE/cseq=1 (rdata0x7fe9340364f8) [2023-04-11 14:53:45] DEBUG[28441]: chan_pjsip.c:2887 chan_pjsip_session_begin: 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: chan_pjsip.c:2891 chan_pjsip_session_begin: Direct media no glare mitigation [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:3954 new_invite: 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:965 _ast_odbc_request_obj2: Reusing ODBC handle 0x5558181300c0 from class 'mysql' [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:115 custom_prepare: Skip: 0; SQL: SELECT * FROM extensions WHERE exten = ? AND priority = ? AND context = ? [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:134 custom_prepare: Parameter 1 ('exten') = '84123456789' [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:134 custom_prepare: Parameter 2 ('priority') = '1' [2023-04-11 14:53:45] DEBUG[28441]: res_config_odbc.c:134 custom_prepare: Parameter 3 ('context') = 'default' [2023-04-11 14:53:45] DEBUG[28441]: res_odbc.c:808 ast_odbc_release_obj: Releasing ODBC handle 0x5558181300c0 into pool [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4038 new_invite: 0123456789: Call (UDP:1.1.1.1:5060) to extension '84123456789' sending 100 Trying [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4681 session_inv_on_state_changed: 0123456789 Event: TSX_STATE Inv State: DISCONNCTD [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4418 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4432 __print_debug_details: The state change pertains to the endpoint '0123456789()' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4437 __print_debug_details: The inv session still has an invite_tsx (0x7fe894018be8) [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4452 __print_debug_details: There is no transaction involved in this state change [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4454 __print_debug_details: The current inv state is DISCONNCTD [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4707 session_inv_on_state_changed: 0123456789: Source of transaction state change is USER [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4754 session_inv_on_state_changed: [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4799 session_inv_on_tsx_state_changed: 0123456789 TSX State: Terminated Inv State: DISCONNCTD [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4418 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4432 __print_debug_details: The state change pertains to the endpoint '0123456789()' [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4440 __print_debug_details: The inv session does NOT have an invite_tsx [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4443 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x7fe894018be8 [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4447 __print_debug_details: The current transaction state is Terminated [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4449 __print_debug_details: The transaction state change event is USER [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4454 __print_debug_details: The current inv state is DISCONNCTD [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4820 session_inv_on_tsx_state_changed: Disconnected [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4219 session_on_tsx_state: (null session) TSX State: Terminated Inv State: DISCONNCTD [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4227 session_on_tsx_state: [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4083 new_invite: 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4174 handle_new_invite_request: Request: Session: 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:4294 session_on_rx_request: (null session) Handled request INVITE ? yes [2023-04-11 14:53:45] DEBUG[28441]: chan_pjsip.c:2908 chan_pjsip_session_end: 0123456789 [2023-04-11 14:53:45] DEBUG[28441]: chan_pjsip.c:2911 chan_pjsip_session_end: No channel [2023-04-11 14:53:45] DEBUG[28441]: res_pjsip_session.c:2912 session_destructor: 0123456789: Destroying SIP session