[Nov 14 14:41:01] Asterisk 14.1.0-rc1 built by root @ dti-asterisk.cegep-fxg.qc.ca on a x86_64 running Linux on 2016-10-19 15:01:00 UTC [Nov 14 14:41:01] DEBUG[10265] config.c: Parsing /etc/asterisk/logger.conf [Nov 14 14:41:01] VERBOSE[10265] config.c: Parsing '/etc/asterisk/logger.conf': Found [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Destroying table cache for Queue_log [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found id column with type -5 with len 20, octetlen 20, and numlen (0,10) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found time column with type -9 with len 26, octetlen 78, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found callid column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found queuename column with type -9 with len 20, octetlen 60, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found agent column with type -9 with len 20, octetlen 60, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found event column with type -9 with len 20, octetlen 60, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data column with type -9 with len 100, octetlen 300, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data1 column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data2 column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data3 column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data4 column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found data5 column with type -9 with len 40, octetlen 120, and numlen (0,0) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Found created column with type 93 with len 19, octetlen 19, and numlen (0,10) [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Skip: 0; SQL: INSERT INTO Queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 1 ('time') = '2016-11-14 14:41:01.184967' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 2 ('data5') = '' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 3 ('data4') = '' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 4 ('data3') = '' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 5 ('data2') = '' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 6 ('data1') = '' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 7 ('event') = 'CONFIGRELOAD' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 8 ('agent') = 'NONE' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 9 ('queuename') = 'NONE' [Nov 14 14:41:01] DEBUG[10265] res_config_odbc.c: Parameter 10 ('callid') = 'NONE' [Nov 14 14:41:01] DEBUG[10265] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:01] VERBOSE[10265] logger.c: Asterisk Queue Logger restarted [Nov 14 14:41:01] DEBUG[28921] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:01] DEBUG[28921] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:29] DEBUG[28913] res_pjsip_registrar_expire.c: Woke up at 1479152489 Interval: 30 [Nov 14 14:41:29] DEBUG[28913] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:29] DEBUG[28913] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE expiration_time <= ? ORDER BY expiration_time [Nov 14 14:41:29] DEBUG[28913] res_config_odbc.c: Parameter 1 ('expiration_time <=') = '1479152489' [Nov 14 14:41:29] DEBUG[28913] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:29] DEBUG[28913] res_pjsip_registrar_expire.c: Expiring 0 contacts [Nov 14 14:41:31] DEBUG[28921] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:31] DEBUG[28921] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=25918 (rdata0x7f27840030b8) [Nov 14 14:41:58] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (481 bytes) from UDP:10.188.6.52:5061 ---> REGISTER sip:206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-6660c983 From: ;tag=5043021c8612c3bfo0 To: Call-ID: 13c586b5-f45fdd7f@10.188.6.52 CSeq: 25918 REGISTER Max-Forwards: 70 Contact: ;expires=3600 User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE Supported: 100rel, replaces [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=25918 (rdata0x7f27840030b8) [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002b to use for Request msg REGISTER/cseq=25918 (rdata0x7f27840030b8) [Nov 14 14:41:58] DEBUG[28894] threadpool.c: Increasing threadpool SIP's size by 5 [Nov 14 14:41:58] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=25918 (rdata0x7f2784006018) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: Source address 10.188.6.52:5061 does not match identify 'sipp' [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: '10.188.6.52:5061' did not match any identify section rules [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172@206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Identified by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] pjproject: endpoint .Response msg 401/REGISTER/cseq=25918 (tdta0x7f2714003a40) created [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_auths WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '206.167.100.39' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port ''. [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (499 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-6660c983 Call-ID: 13c586b5-f45fdd7f@10.188.6.52 From: ;tag=5043021c8612c3bfo0 To: ;tag=z9hG4bK-6660c983 CSeq: 25918 REGISTER WWW-Authenticate: Digest realm="206.167.100.39",nonce="1479152518/7efae294665521b7f961b4a680370a3a",opaque="12e80adf67b463d6",algorithm=md5,qop="auth" Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:41:58] DEBUG[10279] pjproject: tdta0x7f271400 .Destroying txdata Response msg 401/REGISTER/cseq=25918 (tdta0x7f2714003a40) [Nov 14 14:41:58] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=25919 (rdata0x7f27840030b8) [Nov 14 14:41:58] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (745 bytes) from UDP:10.188.6.52:5061 ---> REGISTER sip:206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-e75ea948 From: ;tag=5043021c8612c3bfo0 To: Call-ID: 13c586b5-f45fdd7f@10.188.6.52 CSeq: 25919 REGISTER Max-Forwards: 70 Authorization: Digest username="U_9172",realm="206.167.100.39",nonce="1479152518/7efae294665521b7f961b4a680370a3a",uri="sip:206.167.100.39",algorithm=MD5,response="2907c5d0215bc08a23f489d959820bd3",opaque="12e80adf67b463d6",qop=auth,nc=00000001,cnonce="fbc1cb88" Contact: ;expires=3600 User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE Supported: 100rel, replaces [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=25919 (rdata0x7f27840030b8) [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002b to use for Request msg REGISTER/cseq=25919 (rdata0x7f27840030b8) [Nov 14 14:41:58] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=25919 (rdata0x7f2784006018) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: Source address 10.188.6.52:5061 does not match identify 'sipp' [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: '10.188.6.52:5061' did not match any identify section rules [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172@206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:41:58] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:41:58] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Identified by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] pjproject: endpoint .Response msg 401/REGISTER/cseq=25919 (tdta0x7f2714003a40) created [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_auths WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:58] DEBUG[10279] res_pjsip_authenticator_digest.c: Calculated nonce 1479152518/7efae294665521b7f961b4a680370a3a. Actual nonce is 1479152518/7efae294665521b7f961b4a680370a3a [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '206.167.100.39' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port ''. [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:58] DEBUG[10279] pjproject: tdta0x7f271400 .Destroying txdata Response msg 401/REGISTER/cseq=25919 (tdta0x7f2714003a40) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] res_pjsip_registrar.c: Matched id 'U_9172' to aor 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_pjsip_registrar.c: Matched aor 'U_9172' by To username [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [5061] in [0, 4294967295] gives [5061](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [5061] in [0, 4294967295] gives [5061](0) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: UPDATE ps_contacts SET qualify_timeout=?, reg_server=?, call_id=?, via_addr=?, outbound_proxy=?, expiration_time=?, path=?, endpoint=?, qualify_frequency=?, user_agent=?, authenticate_qualify=?, uri=?, via_port=? WHERE id=? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('qualify_timeout') = '3.000000' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 2 ('reg_server') = '' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 3 ('call_id') = 'd5ed9e46-d72fc320@10.188.6.52' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 4 ('via_addr') = '10.188.6.52' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 5 ('outbound_proxy') = '' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 6 ('expiration_time') = '1479156118' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 7 ('path') = '' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 8 ('endpoint') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 9 ('qualify_frequency') = '0' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 10 ('user_agent') = 'Cisco/SPA514G-7.5.7' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 11 ('authenticate_qualify') = 'no' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 12 ('uri') = 'sip:U_9172@10.188.6.52:5061' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 13 ('via_port') = '5061' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 14 = 'U_9172;@46fd987afadd4bac4bc0cb511c16ea21' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[28867] threadpool.c: Increasing threadpool Sorcery's size by 1 [Nov 14 14:41:58] DEBUG[10279] res_pjsip_registrar.c: Refreshed contact 'sip:U_9172@10.188.6.52:5061' on AOR 'U_9172' with new expiration of 3600 seconds [Nov 14 14:41:58] DEBUG[10284] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [Nov 14 14:41:58] DEBUG[10284] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10284] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[28867] threadpool.c: Increasing threadpool Sorcery's size by 1 [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:41:58] DEBUG[28868] threadpool.c: Increasing threadpool stasis-core's size by 1 [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [5061] in [0, 4294967295] gives [5061](0) [Nov 14 14:41:58] DEBUG[10279] pjproject: endpoint .Response msg 200/REGISTER/cseq=25919 (tdta0x7f2714003a40) created [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f2710044 ..Transaction created for Request msg REGISTER/cseq=25919 (rdata0x7f2784006018) [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f2710044 .Incoming Request msg REGISTER/cseq=25919 (rdata0x7f2784006018) in state Null [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f2710044 ..State changed from Null to Trying, event=RX_MSG [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:41:58] DEBUG[10280] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:41:58] DEBUG[10280] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint U_9172, new messages: 0, old messages: 0 [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10280] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:41:58] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f2710044 .Sending Response msg 200/REGISTER/cseq=25919 (tdta0x7f2714003a40) in state Trying [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (426 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-e75ea948 Call-ID: 13c586b5-f45fdd7f@10.188.6.52 From: ;tag=5043021c8612c3bfo0 To: ;tag=z9hG4bK-e75ea948 CSeq: 25919 REGISTER Date: Mon, 14 Nov 2016 19:41:58 GMT Contact: ;expires=3599 Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f2710044 ..State changed from Trying to Completed, event=TX_MSG [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10280] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract double from [3] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [5061] in [0, 4294967295] gives [5061](0) [Nov 14 14:41:58] DEBUG[10280] pjproject: endpoint Request msg NOTIFY/cseq=9484 (tdta0x7f27100476d0) created. [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:41:58] DEBUG[10280] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:58] DEBUG[10280] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:58] DEBUG[10280] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:41:58] DEBUG[10280] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:41:58] DEBUG[10280] res_pjsip.c: 0x7f2710041050: Wrapper created [Nov 14 14:41:58] DEBUG[10280] pjproject: tsx0x7f271400f .Transaction created for Request msg NOTIFY/cseq=9484 (tdta0x7f27100476d0) [Nov 14 14:41:58] DEBUG[10280] pjproject: tsx0x7f271400f Sending Request msg NOTIFY/cseq=9484 (tdta0x7f27100476d0) in state Null [Nov 14 14:41:58] DEBUG[10280] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.188.6.52' [Nov 14 14:41:58] DEBUG[10280] res_pjsip/pjsip_resolver.c: Transport type for target '10.188.6.52' is 'UDP' [Nov 14 14:41:58] DEBUG[10280] res_pjsip/pjsip_resolver.c: Target '10.188.6.52' is an IP address, skipping resolution [Nov 14 14:41:58] DEBUG[10280] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 206.167.100.39:5060 [Nov 14 14:41:58] DEBUG[10280] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[10280] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[10280] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[10280] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] VERBOSE[10280] res_pjsip_logger.c: <--- Transmitting SIP request (646 bytes) to UDP:10.188.6.52:5061 ---> NOTIFY sip:U_9172@10.188.6.52:5061 SIP/2.0 Via: SIP/2.0/UDP 206.167.100.39:5060;rport;branch=z9hG4bKPj1c80666d-2cea-45f9-b965-ced48aa90c2f From: ;tag=0595b411-2742-46bd-bca8-3f8be0203f67 To: Contact: Call-ID: 5f6e7722-90d6-4ff8-a3af-15fadf770491 CSeq: 9484 NOTIFY Subscription-State: terminated Event: message-summary Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: Asterisk PBX 14.1.0-rc1 Content-Type: application/simple-message-summary Content-Length: 48 Messages-Waiting: no Voice-Message: 0/0 (0/0) [Nov 14 14:41:58] DEBUG[10280] pjproject: tsx0x7f271400f .State changed from Null to Calling, event=TX_MSG [Nov 14 14:41:58] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Response msg 200/NOTIFY/cseq=9484 (rdata0x7f27840030b8) [Nov 14 14:41:58] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP response (352 bytes) from UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK To: ;tag=a06463201fa7368bi0 From: ;tag=0595b411-2742-46bd-bca8-3f8be0203f67 Call-ID: 5f6e7722-90d6-4ff8-a3af-15fadf770491 CSeq: 9484 NOTIFY Via: SIP/2.0/UDP 206.167.100.39:5060;branch=z9hG4bKPj1c80666d-2cea-45f9-b965-ced48aa90c2f Server: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:58] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:58] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: No dialog serializer for response Response msg 200/NOTIFY/cseq=9484 (rdata0x7f27840030b8). Using request transaction as basis [Nov 14 14:41:58] DEBUG[28896] res_pjsip/pjsip_distributor.c: Found serializer pjsip/mwi-0000004b on transaction tsx0x7f271400f7c8 [Nov 14 14:41:58] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 200/NOTIFY/cseq=9484 (rdata0x7f27840084c8) [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f271400f .Incoming Response msg 200/NOTIFY/cseq=9484 (rdata0x7f27840084c8) in state Calling [Nov 14 14:41:58] DEBUG[10279] pjproject: tsx0x7f271400f ..State changed from Calling to Completed, event=RX_MSG [Nov 14 14:41:58] DEBUG[10279] res_pjsip.c: 0x7f2710041050: PJSIP tsx response received [Nov 14 14:41:58] DEBUG[10279] res_pjsip.c: 0x7f2710041050: Callbacks executed [Nov 14 14:41:58] DEBUG[10279] res_pjsip.c: 0x7f2710041050: wrapper destroyed [Nov 14 14:41:59] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg SUBSCRIBE/cseq=26250 (rdata0x7f27840030b8) [Nov 14 14:41:59] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (455 bytes) from UDP:10.188.6.52:5061 ---> SUBSCRIBE sip:Ligne_Socs_Recep@206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-970663e1 From: ;tag=72d13c2187a3c984 To: Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 26250 SUBSCRIBE Max-Forwards: 70 Contact: Accept: application/dialog-info+xml Expires: 1800 Event: dialog User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=26250 (rdata0x7f27840030b8) [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg SUBSCRIBE/cseq=26250 (rdata0x7f27840030b8) [Nov 14 14:41:59] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg SUBSCRIBE/cseq=26250 (rdata0x7f2784008418) [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: Source address 10.188.6.52:5061 does not match identify 'sipp' [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: '10.188.6.52:5061' did not match any identify section rules [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172@206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Identified by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] pjproject: endpoint .Response msg 401/SUBSCRIBE/cseq=26250 (tdta0x7f271003cf70) created [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_auths WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '206.167.100.39' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port ''. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (508 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-970663e1 Call-ID: dccce225-811abb50@10.188.6.52 From: ;tag=72d13c2187a3c984 To: ;tag=z9hG4bK-970663e1 CSeq: 26250 SUBSCRIBE WWW-Authenticate: Digest realm="206.167.100.39",nonce="1479152519/bf1628dd60c79ee8b8dc67f5d22a9577",opaque="248c3637632ae95e",algorithm=md5,qop="auth" Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:41:59] DEBUG[10279] pjproject: tdta0x7f271003 .Destroying txdata Response msg 401/SUBSCRIBE/cseq=26250 (tdta0x7f271003cf70) [Nov 14 14:41:59] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg SUBSCRIBE/cseq=26251 (rdata0x7f27840030b8) [Nov 14 14:41:59] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (735 bytes) from UDP:10.188.6.52:5061 ---> SUBSCRIBE sip:Ligne_Socs_Recep@206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-72ac9481 From: ;tag=72d13c2187a3c984 To: Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 26251 SUBSCRIBE Max-Forwards: 70 Authorization: Digest username="U_9172",realm="206.167.100.39",nonce="1479152519/bf1628dd60c79ee8b8dc67f5d22a9577",uri="sip:Ligne_Socs_Recep@206.167.100.39",algorithm=MD5,response="748ff86c062de32bf1fc59b69d71d1d9",opaque="248c3637632ae95e",qop=auth,nc=00000001,cnonce="dcac529" Contact: Accept: application/dialog-info+xml Expires: 1800 Event: dialog User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg SUBSCRIBE/cseq=26251 (rdata0x7f27840030b8) [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg SUBSCRIBE/cseq=26251 (rdata0x7f27840030b8) [Nov 14 14:41:59] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg SUBSCRIBE/cseq=26251 (rdata0x7f2784008ad8) [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: Source address 10.188.6.52:5061 does not match identify 'sipp' [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: '10.188.6.52:5061' did not match any identify section rules [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172@206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:41:59] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:41:59] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Identified by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:41:59] DEBUG[10279] pjproject: endpoint .Response msg 401/SUBSCRIBE/cseq=26251 (tdta0x7f271003cf70) created [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_auths WHERE id = ? [Nov 14 14:41:59] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:41:59] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:41:59] DEBUG[10279] res_pjsip_authenticator_digest.c: Calculated nonce 1479152519/bf1628dd60c79ee8b8dc67f5d22a9577. Actual nonce is 1479152519/bf1628dd60c79ee8b8dc67f5d22a9577 [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '206.167.100.39' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port ''. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:41:59] DEBUG[10279] pjproject: tdta0x7f271003 .Destroying txdata Response msg 401/SUBSCRIBE/cseq=26251 (tdta0x7f271003cf70) [Nov 14 14:41:59] DEBUG[10279] res_pjsip_pubsub.c: Body generator 0x7f26f5491500 found for accept type application/dialog-info+xml [Nov 14 14:41:59] DEBUG[10279] res_pjsip_pubsub.c: Subscription to resource Ligne_Socs_Recep is not to a list [Nov 14 14:41:59] DEBUG[10279] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003b to use for Request msg SUBSCRIBE/cseq=26251 (rdata0x7f2784008ad8) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710028 ..Transaction created for Request msg SUBSCRIBE/cseq=26251 (rdata0x7f2784008ad8) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710028 .Incoming Request msg SUBSCRIBE/cseq=26251 (rdata0x7f2784008ad8) in state Null [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710028 ..State changed from Null to Trying, event=RX_MSG [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ...Transaction tsx0x7f2710028c98 state changed to Trying [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 .UAS dialog created [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 .Module mod-evsub added as dialog usage, data=0x7f2710065b78 [Nov 14 14:41:59] DEBUG[10279] pjproject: evsub0x7f27100 .UAS subscription created, using dialog dlg0x7f2714005aa8 [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ..Session count inc to 2 by mod-evsub [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ..Session count inc to 2 by PubSub Module [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:41:59] DEBUG[10279] pjproject: endpoint .Response msg 200/SUBSCRIBE/cseq=26251 (tdta0x7f271003cf70) created [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ..Sending Response msg 200/SUBSCRIBE/cseq=26251 (tdta0x7f271003cf70) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710028 ..Sending Response msg 200/SUBSCRIBE/cseq=26251 (tdta0x7f271003cf70) in state Trying [Nov 14 14:41:59] DEBUG[10279] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 206.167.100.39:5060 [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (575 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-72ac9481 Call-ID: dccce225-811abb50@10.188.6.52 From: ;tag=72d13c2187a3c984 To: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 CSeq: 26251 SUBSCRIBE Expires: 1800 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710028 ...State changed from Trying to Completed, event=TX_MSG [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ....Transaction tsx0x7f2710028c98 state changed to Completed [Nov 14 14:41:59] DEBUG[10279] pjproject: evsub0x7f27100 .UAS timeout in 1800 seconds [Nov 14 14:41:59] DEBUG[10279] pjproject: evsub0x7f27100 .Timer UAS_TIMEOUT scheduled in 1800 seconds [Nov 14 14:41:59] DEBUG[10279] devicestate.c: Checking if I can find provider for "Custom" - number: BLF_SOCS_RECEPTION [Nov 14 14:41:59] DEBUG[10279] devicestate.c: Checking provider Agent with Custom [Nov 14 14:41:59] DEBUG[10279] devicestate.c: Checking provider Custom with Custom [Nov 14 14:41:59] DEBUG[10279] db.c: Unable to find key 'BLF_SOCS_RECEPTION' in family 'CustomDevstate' [Nov 14 14:41:59] DEBUG[10279] pjproject: endpoint Request msg NOTIFY/cseq=25613 (tdta0x7f2708007900) created. [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 .Sending Request msg NOTIFY/cseq=25613 (tdta0x7f2708007900) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710035 ..Transaction created for Request msg NOTIFY/cseq=25612 (tdta0x7f2708007900) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710035 .Sending Request msg NOTIFY/cseq=25612 (tdta0x7f2708007900) in state Null [Nov 14 14:41:59] DEBUG[10279] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.188.6.52' [Nov 14 14:41:59] DEBUG[10279] res_pjsip/pjsip_resolver.c: Transport type for target '10.188.6.52' is 'UDP' [Nov 14 14:41:59] DEBUG[10279] res_pjsip/pjsip_resolver.c: Target '10.188.6.52' is an IP address, skipping resolution [Nov 14 14:41:59] DEBUG[10279] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 206.167.100.39:5060 [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP request (869 bytes) to UDP:10.188.6.52:5061 ---> NOTIFY sip:U_9172@10.188.6.52:5061 SIP/2.0 Via: SIP/2.0/UDP 206.167.100.39:5060;rport;branch=z9hG4bKPj094c3365-f4eb-42c3-a349-55e22d1cec7b From: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 To: ;tag=72d13c2187a3c984 Contact: Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 25612 NOTIFY Event: dialog Subscription-State: active;expires=1799 Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: Asterisk PBX 14.1.0-rc1 Content-Type: application/dialog-info+xml Content-Length: 257 terminated [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710035 ..State changed from Null to Calling, event=TX_MSG [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ...Transaction tsx0x7f2710035c68 state changed to Calling [Nov 14 14:41:59] DEBUG[10279] pjproject: evsub0x7f27100 Subscription state changed NULL --> ACTIVE [Nov 14 14:41:59] DEBUG[10279] res_pjsip_pubsub.c: on_evsub_state called with state ACTIVE [Nov 14 14:41:59] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Response msg 200/NOTIFY/cseq=25612 (rdata0x7f27840030b8) [Nov 14 14:41:59] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP response (357 bytes) from UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK To: ;tag=72d13c2187a3c984 From: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 25612 NOTIFY Via: SIP/2.0/UDP 206.167.100.39:5060;branch=z9hG4bKPj094c3365-f4eb-42c3-a349-55e22d1cec7b Server: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:41:59] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:41:59] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f2714005aa8 for Response msg 200/NOTIFY/cseq=25612 (rdata0x7f27840030b8) [Nov 14 14:41:59] DEBUG[28896] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003b on dialog dlg0x7f2714005aa8 [Nov 14 14:41:59] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 200/NOTIFY/cseq=25612 (rdata0x7f2784008348) [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710035 .Incoming Response msg 200/NOTIFY/cseq=25612 (rdata0x7f2784008348) in state Calling [Nov 14 14:41:59] DEBUG[10279] pjproject: tsx0x7f2710035 ..State changed from Calling to Completed, event=RX_MSG [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ...Received Response msg 200/NOTIFY/cseq=25612 (rdata0x7f2784008348) [Nov 14 14:41:59] DEBUG[10279] pjproject: dlg0x7f2714005 ...Transaction tsx0x7f2710035c68 state changed to Completed [Nov 14 14:41:59] DEBUG[28913] res_pjsip_registrar_expire.c: Woke up at 1479152519 Interval: 30 [Nov 14 14:41:59] DEBUG[28913] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:41:59] DEBUG[28913] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE expiration_time <= ? ORDER BY expiration_time [Nov 14 14:41:59] DEBUG[28913] res_config_odbc.c: Parameter 1 ('expiration_time <=') = '1479152519' [Nov 14 14:41:59] DEBUG[28913] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:41:59] DEBUG[28913] res_pjsip_registrar_expire.c: Expiring 0 contacts [Nov 14 14:42:01] DEBUG[28921] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:01] DEBUG[28921] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:03] DEBUG[28896] pjproject: tsx0x7f271400f Timeout timer event [Nov 14 14:42:03] DEBUG[28896] pjproject: tsx0x7f271400f .State changed from Completed to Terminated, event=TIMER [Nov 14 14:42:03] DEBUG[28896] pjproject: tsx0x7f271400f Timeout timer event [Nov 14 14:42:03] DEBUG[28896] pjproject: tsx0x7f271400f .State changed from Terminated to Destroyed, event=TIMER [Nov 14 14:42:03] DEBUG[28896] pjproject: tdta0x7f271004 ..Destroying txdata Request msg NOTIFY/cseq=9484 (tdta0x7f27100476d0) [Nov 14 14:42:03] DEBUG[28896] pjproject: tsx0x7f271400f Transaction destroyed! [Nov 14 14:42:04] DEBUG[28896] pjproject: tsx0x7f2710035 Timeout timer event [Nov 14 14:42:04] DEBUG[28896] pjproject: tsx0x7f2710035 .State changed from Completed to Terminated, event=TIMER [Nov 14 14:42:04] DEBUG[28896] pjproject: dlg0x7f2714005 ..Transaction tsx0x7f2710035c68 state changed to Terminated [Nov 14 14:42:04] DEBUG[28896] pjproject: tsx0x7f2710035 Timeout timer event [Nov 14 14:42:04] DEBUG[28896] pjproject: tsx0x7f2710035 .State changed from Terminated to Destroyed, event=TIMER [Nov 14 14:42:04] DEBUG[28896] pjproject: tdta0x7f270800 ..Destroying txdata Request msg NOTIFY/cseq=25612 (tdta0x7f2708007900) [Nov 14 14:42:04] DEBUG[28896] pjproject: tsx0x7f2710035 Transaction destroyed! [Nov 14 14:42:14] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg SUBSCRIBE/cseq=26252 (rdata0x7f27840030b8) [Nov 14 14:42:14] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (773 bytes) from UDP:10.188.6.52:5061 ---> SUBSCRIBE sip:Ligne_Socs_Recep@206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-ee1952d0 From: ;tag=72d13c2187a3c984 To: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 26252 SUBSCRIBE Max-Forwards: 70 Authorization: Digest username="U_9172",realm="206.167.100.39",nonce="1479152519/bf1628dd60c79ee8b8dc67f5d22a9577",uri="sip:Ligne_Socs_Recep@206.167.100.39",algorithm=MD5,response="f682b87653b31ac30011e88c6bacf4ca",opaque="248c3637632ae95e",qop=auth,nc=00000002,cnonce="dcac529" Contact: Accept: application/dialog-info+xml Expires: 0 Event: dialog User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f2714005aa8 for Request msg SUBSCRIBE/cseq=26252 (rdata0x7f27840030b8) [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003b on dialog dlg0x7f2714005aa8 [Nov 14 14:42:14] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg SUBSCRIBE/cseq=26252 (rdata0x7f2784008b28) [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 .Received Request msg SUBSCRIBE/cseq=26252 (rdata0x7f2784008b28) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710035 ...Transaction created for Request msg SUBSCRIBE/cseq=26252 (rdata0x7f2784008b28) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710035 ..Incoming Request msg SUBSCRIBE/cseq=26252 (rdata0x7f2784008b28) in state Null [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710035 ...State changed from Null to Trying, event=RX_MSG [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ....Transaction tsx0x7f2710035c68 state changed to Trying [Nov 14 14:42:14] DEBUG[10279] pjproject: endpoint .....Response msg 200/SUBSCRIBE/cseq=26252 (tdta0x7f27100476d0) created [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ......Sending Response msg 200/SUBSCRIBE/cseq=26252 (tdta0x7f27100476d0) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710035 ......Sending Response msg 200/SUBSCRIBE/cseq=26252 (tdta0x7f27100476d0) in state Trying [Nov 14 14:42:14] DEBUG[10279] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 206.167.100.39:5060 [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (572 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-ee1952d0 Call-ID: dccce225-811abb50@10.188.6.52 From: ;tag=72d13c2187a3c984 To: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 CSeq: 26252 SUBSCRIBE Expires: 0 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710035 .......State changed from Trying to Completed, event=TX_MSG [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ........Transaction tsx0x7f2710035c68 state changed to Completed [Nov 14 14:42:14] DEBUG[10279] pjproject: evsub0x7f27100 .....Subscription state changed TERMINATED --> TERMINATED [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: on_evsub_state called with state TERMINATED [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: Possible terminate race prevented 0x7f2710056360 [Nov 14 14:42:14] DEBUG[10279] pjproject: endpoint Request msg NOTIFY/cseq=25614 (tdta0x7f2708007900) created. [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 .Sending Request msg NOTIFY/cseq=25614 (tdta0x7f2708007900) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f271400f ..Transaction created for Request msg NOTIFY/cseq=25613 (tdta0x7f2708007900) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f271400f .Sending Request msg NOTIFY/cseq=25613 (tdta0x7f2708007900) in state Null [Nov 14 14:42:14] DEBUG[10279] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.188.6.52' [Nov 14 14:42:14] DEBUG[10279] res_pjsip/pjsip_resolver.c: Transport type for target '10.188.6.52' is 'UDP' [Nov 14 14:42:14] DEBUG[10279] res_pjsip/pjsip_resolver.c: Target '10.188.6.52' is an IP address, skipping resolution [Nov 14 14:42:14] DEBUG[10279] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 206.167.100.39:5060 [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP request (860 bytes) to UDP:10.188.6.52:5061 ---> NOTIFY sip:U_9172@10.188.6.52:5061 SIP/2.0 Via: SIP/2.0/UDP 206.167.100.39:5060;rport;branch=z9hG4bKPj8763c720-e539-4b9e-9494-7b148cfad8c1 From: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 To: ;tag=72d13c2187a3c984 Contact: Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 25613 NOTIFY Event: dialog Subscription-State: terminated Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: Asterisk PBX 14.1.0-rc1 Content-Type: application/dialog-info+xml Content-Length: 257 terminated [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f271400f ..State changed from Null to Calling, event=TX_MSG [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ...Transaction tsx0x7f271400f7c8 state changed to Calling [Nov 14 14:42:14] DEBUG[10279] pjproject: evsub.c ....Subscription already terminated for NOTIFY, event=dialog;id= [Nov 14 14:42:14] DEBUG[10279] pjproject: evsub0x7f27100 Subscription state changed TERMINATED --> TERMINATED [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: on_evsub_state called with state TERMINATED [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: Removing subscription to resource Ligne_Socs_Recep from list of subscriptions [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: Removing subscription 0x7f2710042d80 reference to subscription tree 0x7f2710056360 [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: Destroying subscription tree 0x7f2710056360 [Nov 14 14:42:14] DEBUG[10279] res_pjsip_pubsub.c: Destroying SIP subscription to resource Ligne_Socs_Recep [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 .Session count dec to 1 by PubSub Module [Nov 14 14:42:14] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=25920 (rdata0x7f27840030b8) [Nov 14 14:42:14] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP request (742 bytes) from UDP:10.188.6.52:5061 ---> REGISTER sip:206.167.100.39 SIP/2.0 Via: SIP/2.0/UDP 10.188.6.52:5061;branch=z9hG4bK-c65790cd From: ;tag=5043021c8612c3bfo0 To: Call-ID: 13c586b5-f45fdd7f@10.188.6.52 CSeq: 25920 REGISTER Max-Forwards: 70 Authorization: Digest username="U_9172",realm="206.167.100.39",nonce="1479152518/7efae294665521b7f961b4a680370a3a",uri="sip:206.167.100.39",algorithm=MD5,response="e375b0f5fcf54ed3ffd8e0180a03b51e",opaque="12e80adf67b463d6",qop=auth,nc=00000002,cnonce="fbc1cb88" Contact: ;expires=0 User-Agent: Cisco/SPA514G-7.5.7 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE Supported: 100rel, replaces [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=25920 (rdata0x7f27840030b8) [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000002b to use for Request msg REGISTER/cseq=25920 (rdata0x7f27840030b8) [Nov 14 14:42:14] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=25920 (rdata0x7f2784008e88) [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoint_id_ips WHERE id LIKE ? ORDER BY id [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = '%' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:42:14] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: Source address 10.188.6.52:5061 does not match identify 'sipp' [Nov 14 14:42:14] DEBUG[10279] res_pjsip_endpoint_identifier_ip.c: '10.188.6.52:5061' did not match any identify section rules [Nov 14 14:42:14] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172@206.167.100.39' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:42:14] DEBUG[10279] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:42:14] DEBUG[10279] res_pjsip_endpoint_identifier_user.c: Identified by From username 'U_9172' domain '206.167.100.39' [Nov 14 14:42:14] DEBUG[10279] pjproject: endpoint .Response msg 401/REGISTER/cseq=25920 (tdta0x7f2784002080) created [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_auths WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [32] in [0, 4294967295] gives [32](0) [Nov 14 14:42:14] DEBUG[10279] res_pjsip_authenticator_digest.c: Calculated nonce 1479152518/7efae294665521b7f961b4a680370a3a. Actual nonce is 1479152518/7efae294665521b7f961b4a680370a3a [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '206.167.100.39' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port ''. [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '10.188.6.52' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port ''. [Nov 14 14:42:14] DEBUG[10279] pjproject: tdta0x7f278400 .Destroying txdata Response msg 401/REGISTER/cseq=25920 (tdta0x7f2784002080) [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_domain_aliases WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = '206.167.100.39' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] res_pjsip_registrar.c: Matched id 'U_9172' to aor 'U_9172' [Nov 14 14:42:14] DEBUG[10279] res_pjsip_registrar.c: Matched aor 'U_9172' by To username [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract double from [3] in [-inf, inf] gives [3.000000](0) [Nov 14 14:42:14] DEBUG[10279] config.c: extract uint from [5061] in [0, 4294967295] gives [5061](0) [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: DELETE FROM ps_contacts WHERE id=? [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 = 'U_9172;@46fd987afadd4bac4bc0cb511c16ea21' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] VERBOSE[10279] res_pjsip_registrar.c: Removed contact 'sip:U_9172@10.188.6.52:5061' from AOR 'U_9172' due to request [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] VERBOSE[10284] res_pjsip/pjsip_configuration.c: Contact U_9172/sip:U_9172@10.188.6.52:5061 has been deleted [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:42:14] DEBUG[10279] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:42:14] DEBUG[10279] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10279] pjproject: endpoint .Response msg 200/REGISTER/cseq=25920 (tdta0x7f2784002080) created [Nov 14 14:42:14] DEBUG[10284] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710039 ..Transaction created for Request msg REGISTER/cseq=25920 (rdata0x7f2784008e88) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710039 .Incoming Request msg REGISTER/cseq=25920 (rdata0x7f2784008e88) in state Null [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710039 ..State changed from Null to Trying, event=RX_MSG [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710039 .Sending Response msg 200/REGISTER/cseq=25920 (tdta0x7f2784002080) in state Trying [Nov 14 14:42:14] DEBUG[10284] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_aors WHERE id = ? [Nov 14 14:42:14] DEBUG[10284] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[10279] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[10279] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] VERBOSE[10279] res_pjsip_logger.c: <--- Transmitting SIP response (373 bytes) to UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.188.6.52:5061;rport=5061;received=10.188.6.52;branch=z9hG4bK-c65790cd Call-ID: 13c586b5-f45fdd7f@10.188.6.52 From: ;tag=5043021c8612c3bfo0 To: ;tag=z9hG4bK-c65790cd CSeq: 25920 REGISTER Date: Mon, 14 Nov 2016 19:42:14 GMT Server: Asterisk PBX 14.1.0-rc1 Content-Length: 0 [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f2710039 ..State changed from Trying to Completed, event=TX_MSG [Nov 14 14:42:14] DEBUG[10284] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[10284] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [1] in [0, 4294967295] gives [1](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [60] in [0, 4294967295] gives [60](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [0] in [0, 86400] gives [0](0) [Nov 14 14:42:14] DEBUG[10284] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0) [Nov 14 14:42:14] DEBUG[10284] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[10284] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_contacts WHERE id LIKE ? ORDER BY id [Nov 14 14:42:14] DEBUG[10284] res_config_odbc.c: Parameter 1 ('id LIKE') = 'U_9172;@%' [Nov 14 14:42:14] DEBUG[10284] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] VERBOSE[10284] res_pjsip/pjsip_configuration.c: Endpoint U_9172 is now Unreachable [Nov 14 14:42:14] DEBUG[28879] devicestate.c: No provider found, checking channel drivers for PJSIP - U_9172 [Nov 14 14:42:14] DEBUG[28879] res_odbc.c: Reusing ODBC handle 0x1f57340 from class 'asterisk' [Nov 14 14:42:14] DEBUG[28879] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ? [Nov 14 14:42:14] DEBUG[28879] res_config_odbc.c: Parameter 1 ('id') = 'U_9172' [Nov 14 14:42:14] DEBUG[28879] res_odbc.c: Releasing ODBC handle 0x1f57340 into pool [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'garneau_nom' from retrieval [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'garneau_extension' from retrieval [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'garneau_bureau' from retrieval [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'garneau_relais' from retrieval [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'garneau_cisco_cfa' from retrieval [Nov 14 14:42:14] DEBUG[28879] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [90] in [0, 4294967295] gives [90](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [400] in [0, 4294967295] gives [400](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [Nov 14 14:42:14] DEBUG[28879] config.c: extract uint from [6] in [0, 4294967295] gives [6](0) [Nov 14 14:42:14] DEBUG[28879] devicestate.c: Changing state for PJSIP/U_9172 - state 5 (Unavailable) [Nov 14 14:42:14] DEBUG[28924] app_queue.c: Device 'PJSIP/U_9172' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Nov 14 14:42:14] DEBUG[28896] pjproject: sip_endpoint.c Processing incoming message: Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840030b8) [Nov 14 14:42:14] VERBOSE[28896] res_pjsip_logger.c: <--- Received SIP response (357 bytes) from UDP:10.188.6.52:5061 ---> SIP/2.0 200 OK To: ;tag=72d13c2187a3c984 From: ;tag=dec3b450-ad61-475c-9ea1-9d9f0ba2cc88 Call-ID: dccce225-811abb50@10.188.6.52 CSeq: 25613 NOTIFY Via: SIP/2.0/UDP 206.167.100.39:5060;branch=z9hG4bKPj8763c720-e539-4b9e-9494-7b148cfad8c1 Server: Cisco/SPA514G-7.5.7 Content-Length: 0 [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '10.188.6.52:5061' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '10.188.6.52' and port '5061'. [Nov 14 14:42:14] DEBUG[28896] netsock2.c: Splitting '206.167.100.39:5060' into... [Nov 14 14:42:14] DEBUG[28896] netsock2.c: ...host '206.167.100.39' and port '5060'. [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f2714005aa8 for Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840030b8) [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: No dialog serializer for response Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840030b8). Using request transaction as basis [Nov 14 14:42:14] DEBUG[28896] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-0000003b on transaction tsx0x7f271400f7c8 [Nov 14 14:42:14] DEBUG[10279] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840084f8) [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f271400f .Incoming Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840084f8) in state Calling [Nov 14 14:42:14] DEBUG[10279] pjproject: tsx0x7f271400f ..State changed from Calling to Completed, event=RX_MSG [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ...Received Response msg 200/NOTIFY/cseq=25613 (rdata0x7f27840084f8) [Nov 14 14:42:14] DEBUG[10279] pjproject: dlg0x7f2714005 ...Transaction tsx0x7f271400f7c8 state changed to Completed [Nov 14 14:42:19] DEBUG[28896] pjproject: tsx0x7f271400f Timeout timer event [Nov 14 14:42:19] DEBUG[28896] pjproject: tsx0x7f271400f .State changed from Completed to Terminated, event=TIMER [Nov 14 14:42:19] DEBUG[28896] pjproject: dlg0x7f2714005 ..Transaction tsx0x7f271400f7c8 state changed to Terminated [Nov 14 14:42:19] DEBUG[28896] pjproject: evsub.c ...Subscription already terminated for NOTIFY, event=dialog;id= [Nov 14 14:42:19] DEBUG[28896] pjproject: tsx0x7f271400f Timeout timer event [Nov 14 14:42:19] DEBUG[28896] pjproject: tsx0x7f271400f .State changed from Terminated to Destroyed, event=TIMER [Nov 14 14:42:19] DEBUG[28896] pjproject: tdta0x7f270800 ..Destroying txdata Request msg NOTIFY/cseq=25613 (tdta0x7f2708007900) [Nov 14 14:42:19] DEBUG[28896] pjproject: tsx0x7f271400f Transaction destroyed!