vpbxdev*CLI> [Oct 2 14:09:16] DEBUG[54877]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=45 (rdata0x1ab0268) [Oct 2 14:09:16] <--- Received SIP request (483 bytes) from UDP:192.168.10.99:1024 ---> [Oct 2 14:09:16] REGISTER sip:192.168.10.102 SIP/2.0 [Oct 2 14:09:16] Via: SIP/2.0/UDP 192.168.10.99:1024;branch=z9hG4bK-opcnu91kx7cx;rport [Oct 2 14:09:16] From: "888888" ;tag=jcu6mt40mg [Oct 2 14:09:16] To: "888888" [Oct 2 14:09:16] Call-ID: 386d4404752a-230lf306f0pu [Oct 2 14:09:16] CSeq: 45 REGISTER [Oct 2 14:09:16] Max-Forwards: 70 [Oct 2 14:09:16] Contact: ;reg-id=1;q=1.0 [Oct 2 14:09:16] User-Agent: snom820/8.7.3.19 [Oct 2 14:09:16] Allow-Events: dialog [Oct 2 14:09:16] X-Real-IP: 192.168.10.99 [Oct 2 14:09:16] Supported: path [Oct 2 14:09:16] Expires: 600 [Oct 2 14:09:16] Content-Length: 0 [Oct 2 14:09:16] [Oct 2 14:09:16] [Oct 2 14:09:16] DEBUG[54877]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99:1024' into... [Oct 2 14:09:16] DEBUG[54877]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port '1024'. [Oct 2 14:09:16] DEBUG[54877]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Oct 2 14:09:16] DEBUG[54877]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Oct 2 14:09:16] DEBUG[54872]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=45 (rdata0x1ea1378) [Oct 2 14:09:16] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Oct 2 14:09:16] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id LIKE') = '%' [Oct 2 14:09:16] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:16] DEBUG[54872]: res_pjsip_endpoint_identifier_ip.c:128 ip_identify: No identify sections to match against [Oct 2 14:09:16] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:16] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '888888@192.168.10.102' [Oct 2 14:09:16] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '888888' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'ID' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'TRANSPORT' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'AORS' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'AUTH' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'CONTEXT' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'DISALLOW' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'ALLOW' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'DIRECT_MEDIA' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username '888888' [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = 'anonymous@192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = 'anonymous' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] NOTICE[54872]: res_pjsip/pjsip_distributor.c:251 log_unidentified_request: Request from '"888888" ' failed for '192.168.10.99:1024' (callid: 386d4404752a-230lf306f0pu) - No matching endpoint found [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.66.130' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.66.130' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port ''. [Oct 2 14:09:17] DEBUG[54872]: pjsip:0 : endpoint .Response msg 401/REGISTER/cseq=45 (tdta0x1bcb310) created [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.66.130' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.66.130' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99:1024' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port '1024'. [Oct 2 14:09:17] <--- Transmitting SIP response (470 bytes) to UDP:192.168.10.99:1024 ---> [Oct 2 14:09:17] SIP/2.0 401 Unauthorized [Oct 2 14:09:17] Via: SIP/2.0/UDP 192.168.10.99:1024;rport;received=192.168.10.99;branch=z9hG4bK-opcnu91kx7cx [Oct 2 14:09:17] Call-ID: 386d4404752a-230lf306f0pu [Oct 2 14:09:17] From: "888888" ;tag=jcu6mt40mg [Oct 2 14:09:17] To: "888888" ;tag=z9hG4bK-opcnu91kx7cx [Oct 2 14:09:17] CSeq: 45 REGISTER [Oct 2 14:09:17] WWW-Authenticate: Digest realm="asterisk",nonce="1412251757/5981a68d554b0f8459066c1e1ac7f94d",opaque="5921315723c2501b",algorithm=md5,qop="auth" [Oct 2 14:09:17] Content-Length: 0 [Oct 2 14:09:17] [Oct 2 14:09:17] [Oct 2 14:09:17] DEBUG[54872]: pjsip:0 : tdta0x1bcb310 .Destroying txdata Response msg 401/REGISTER/cseq=45 (tdta0x1bcb310) [Oct 2 14:09:17] DEBUG[54877]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=46 (rdata0x1ab0268) [Oct 2 14:09:17] <--- Received SIP request (741 bytes) from UDP:192.168.10.99:1024 ---> [Oct 2 14:09:17] REGISTER sip:192.168.10.102 SIP/2.0 [Oct 2 14:09:17] Via: SIP/2.0/UDP 192.168.10.99:1024;branch=z9hG4bK-1517ppwlxaui;rport [Oct 2 14:09:17] From: "888888" ;tag=jcu6mt40mg [Oct 2 14:09:17] To: "888888" [Oct 2 14:09:17] Call-ID: 386d4404752a-230lf306f0pu [Oct 2 14:09:17] CSeq: 46 REGISTER [Oct 2 14:09:17] Max-Forwards: 70 [Oct 2 14:09:17] Contact: ;reg-id=1;q=1.0 [Oct 2 14:09:17] User-Agent: snom820/8.7.3.19 [Oct 2 14:09:17] Allow-Events: dialog [Oct 2 14:09:17] X-Real-IP: 192.168.10.99 [Oct 2 14:09:17] Supported: path [Oct 2 14:09:17] Authorization: Digest username="888888",realm="asterisk",nonce="1412251757/5981a68d554b0f8459066c1e1ac7f94d",uri="sip:192.168.10.102",qop=auth,nc=00000001,cnonce="1e741fe1",response="3a25d7795875a559095cf0e75d42bf11",opaque="5921315723c2501b",algorithm=MD5 [Oct 2 14:09:17] Expires: 600 [Oct 2 14:09:17] Content-Length: 0 [Oct 2 14:09:17] [Oct 2 14:09:17] [Oct 2 14:09:17] DEBUG[54877]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99:1024' into... [Oct 2 14:09:17] DEBUG[54877]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port '1024'. [Oct 2 14:09:17] DEBUG[54877]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Oct 2 14:09:17] DEBUG[54877]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Oct 2 14:09:17] DEBUG[54872]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=46 (rdata0x1ea32d8) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id LIKE') = '%' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_pjsip_endpoint_identifier_ip.c:128 ip_identify: No identify sections to match against [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '888888@192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '888888' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'ID' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'TRANSPORT' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'AORS' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'AUTH' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'CONTEXT' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'DISALLOW' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'ALLOW' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_sorcery_realtime.c:119 sorcery_realtime_filter_objectset: Filtering out realtime field 'DIRECT_MEDIA' from retrieval [Oct 2 14:09:17] DEBUG[54872]: res_pjsip_endpoint_identifier_user.c:106 username_identify: Could not identify endpoint by username '888888' [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = 'anonymous@192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = '192.168.10.102' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:113 custom_prepare: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Oct 2 14:09:17] DEBUG[54872]: res_config_odbc.c:129 custom_prepare: Parameter 1 ('id') = 'anonymous' [Oct 2 14:09:17] DEBUG[54872]: res_odbc.c:1062 odbc_release_obj2: odbc_release_obj2(0x18eee38) called (obj->txf = (nil)) [Oct 2 14:09:17] NOTICE[54872]: res_pjsip/pjsip_distributor.c:251 log_unidentified_request: Request from '"888888" ' failed for '192.168.10.99:1024' (callid: 386d4404752a-230lf306f0pu) - No matching endpoint found [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.66.130' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.66.130' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port ''. [Oct 2 14:09:17] DEBUG[54872]: pjsip:0 : endpoint .Response msg 401/REGISTER/cseq=46 (tdta0x1bcb310) created [Oct 2 14:09:17] DEBUG[54872]: res_pjsip_authenticator_digest.c:250 check_nonce: Calculated nonce 1412251757/5981a68d554b0f8459066c1e1ac7f94d. Actual nonce is 1412251757/5981a68d554b0f8459066c1e1ac7f94d [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.66.130' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.66.130' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port ''. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.10.99:1024' into... [Oct 2 14:09:17] DEBUG[54872]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.10.99' and port '1024'. [Oct 2 14:09:17] <--- Transmitting SIP response (470 bytes) to UDP:192.168.10.99:1024 ---> [Oct 2 14:09:17] SIP/2.0 401 Unauthorized [Oct 2 14:09:17] Via: SIP/2.0/UDP 192.168.10.99:1024;rport;received=192.168.10.99;branch=z9hG4bK-1517ppwlxaui [Oct 2 14:09:17] Call-ID: 386d4404752a-230lf306f0pu [Oct 2 14:09:17] From: "888888" ;tag=jcu6mt40mg [Oct 2 14:09:17] To: "888888" ;tag=z9hG4bK-1517ppwlxaui [Oct 2 14:09:17] CSeq: 46 REGISTER [Oct 2 14:09:17] WWW-Authenticate: Digest realm="asterisk",nonce="1412251757/5981a68d554b0f8459066c1e1ac7f94d",opaque="03ec5b3e4215341f",algorithm=md5,qop="auth" [Oct 2 14:09:17] Content-Length: 0 [Oct 2 14:09:17] [Oct 2 14:09:17] [Oct 2 14:09:17] DEBUG[54872]: pjsip:0 : tdta0x1bcb310 .Destroying txdata Response msg 401/REGISTER/cseq=46 (tdta0x1bcb310) vpbxdev*CLI> exit