[OpenSIPS-Users] How to register correctly with pn_enable?
L JO
maybe149365 at gmail.com
Thu Jun 24 09:24:33 EST 2021
I tried to enable push notifications, but the event E_UL_CONTACT REFRESH
never triggered.
This is a register request.
===================================================================================
2021/06/24 06:18:07.886057 10.0.2.90:60730 -> 10.0.2.208:5060
REGISTER sip:sip.mydomain.com SIP/2.0
Via: SIP/2.0/UDP 192.168.31.223:59600;branch=z9hG4bK.3xtl2uq~l;rport
From: <sip:user1 at sip.mydomain.com>;tag=zU9QsB04H
To: sip:user1 at sip.mydomain.com
CSeq: 20 REGISTER
Call-ID: HG8td6g-yW
Max-Forwards: 70
Supported: replaces, outbound, gruu
Accept: application/sdp
Accept: text/plain
Accept: application/vnd.gsma.rcs-ft-http+xml
Contact: <sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp>;+sip.instance="<urn:uuid:8e9c71c9-9279-00c5-99fe-c0f80d147511>"
Expires: 30
User-Agent: Unknown (belle-sip/4.3.0)
===================================================================================
register response
===================================================================================
2021/06/24 06:18:07.905925 10.0.2.208:5060 -> 10.0.2.90:60730
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.31.223:59600
;received=10.0.2.90;branch=z9hG4bK.3xtl2uq~l;rport=60730
From: <sip:user1 at sip.mydomain.com>;tag=zU9QsB04H
To: sip:user1 at sip.mydomain.com;tag=a98d.651a3aa6bda257b01dde8bf25e217bdd
CSeq: 20 REGISTER
Call-ID: HG8td6g-yW
Contact: <sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp>;expires=300
Server: OpenSIPS (3.1.2 (x86_64/linux))
Content-Length: 0
===================================================================================
opensips.cfg
===================================================================================
####### Global Parameters #########
/* uncomment the following lines to enable debugging */
debug_mode=yes
log_level=4
xlog_level=4
log_stderror=yes
log_facility=LOG_LOCAL0
udp_workers=4
/* uncomment the next line to enable the auto temporary blacklisting of
not available destinations (default disabled) */
#disable_dns_blacklist=no
/* uncomment the next line to enable IPv6 lookup after IPv4 dns
lookup failures (default disabled) */
#dns_try_ipv6=yes
socket=udp:10.0.2.208:5060 # CUSTOMIZE ME
alias=udp:10.0.2.208:5060
alias=udp:sip.mydomain.com:5060
db_default_url="mysql://opensips_user:password@127.0.0.1/opensips"
####### Modules Section ########
#set module path
mpath="/usr/lib/x86_64-linux-gnu/opensips/modules/"
#### SIGNALING module
loadmodule "signaling.so"
#### StateLess module
loadmodule "sl.so"
#### Transaction Module
loadmodule "tm.so"
modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)
#### Record Route Module
loadmodule "rr.so"
/* do not append from tag to the RR (no need for this script) */
modparam("rr", "append_fromtag", 0)
#### MAX ForWarD module
loadmodule "maxfwd.so"
#### SIP MSG OPerationS module
loadmodule "sipmsgops.so"
#### FIFO Management Interface
loadmodule "mi_fifo.so"
modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")
modparam("mi_fifo", "fifo_mode", 0666)
#### MYSQL module
loadmodule "db_mysql.so"
#### USeR LOCation module
loadmodule "usrloc.so"
modparam("usrloc", "nat_bflag", "NAT")
modparam("usrloc", "working_mode_preset", "sql-only")
modparam("usrloc", "contact_refresh_timer", true)
#### REGISTRAR module
loadmodule "registrar.so"
modparam("registrar", "tcp_persistent_flag", "TCP_PERSISTENT")
modparam("registrar", "pn_enable", true)
modparam("registrar", "pn_providers", "fcm")
modparam("registrar", "pn_enable_purr", true)
modparam("registrar", "min_expires", 300)
#### ACCounting module
loadmodule "acc.so"
/* what special events should be accounted ? */
modparam("acc", "early_media", 0)
modparam("acc", "report_cancels", 0)
/* by default we do not adjust the direct of the sequential requests.
if you enable this parameter, be sure to enable "append_fromtag"
in "rr" module */
modparam("acc", "detect_direction", 0)
loadmodule "event_routing.so"
loadmodule "event_route.so"
loadmodule "proto_udp.so"
####### Routing Logic ########
# main request routing logic
route{
if (!mf_process_maxfwd_header(10)) {
send_reply(483,"Too Many Hops");
exit;
}
if (has_totag()) {
# handle hop-by-hop ACK (no routing required)
if ( is_method("ACK") && t_check_trans() ) {
t_relay();
exit;
}
# sequential request within a dialog should
# take the path determined by record-routing
if ( !loose_route() ) {
# we do record-routing for all our traffic, so we
should not
# receive any sequential requests without Route hdr.
send_reply(404,"Not here");
exit;
}
if (!is_method("ACK")) {
async (pn_process_purr("location"), resume_route);
}
# route it out to whatever destination was set by
loose_route()
# in $du (destination URI).
route(resume_route);
exit;
}
# CANCEL processing
if (is_method("CANCEL")) {
if (t_check_trans())
t_relay();
exit;
}
# absorb retransmissions, but do not create transaction
t_check_trans();
if ( !(is_method("REGISTER") ) ) {
if (is_myself("$fd")) {
} else {
# if caller is not local, then called number must
be local
if (!is_myself("$rd")) {
send_reply(403,"Relay Forbidden");
exit;
}
}
}
# preloaded route checking
if (loose_route()) {
xlog("L_ERR",
"Attempt to route with preloaded Route's
[$fu/$tu/$ru/$ci]");
if (!is_method("ACK"))
send_reply(403,"Preload Route denied");
exit;
}
# record routing
if (!is_method("REGISTER|MESSAGE"))
record_route();
# account only INVITEs
if (is_method("INVITE")) {
do_accounting("log");
}
if (!is_myself("$rd")) {
append_hf("P-hint: outbound\r\n");
route(relay);
}
# requests for my domain
if (is_method("PUBLISH|SUBSCRIBE")) {
send_reply(503, "Service Unavailable");
exit;
}
if (is_method("REGISTER")) {
# store the registration and generate a SIP reply
if (!save("location"))
xlog("failed to register AoR $tu\n");
exit;
}
if ($rU==NULL) {
# request with no Username in RURI
send_reply(484,"Address Incomplete");
exit;
}
# do lookup with method filtering
#if (!lookup("location","m")) {
# t_reply(404, "Not Found");
# exit;
#}
$avp(skip_relay) = false;
lookup("location","m");
$var(rc) = $retcode;
switch ($var(rc)) {
case 1:
break;
case 2:
$avp(skip_relay) = true;
break;
default:
t_reply(404, "Not Found");
exit;
}
# when routing via usrloc, log the missed calls also
do_accounting("log","missed");
route(relay);
}
route[relay] {
# for INVITEs enable some additional helper routes
if (is_method("INVITE")) {
t_on_branch("per_branch_ops");
t_on_reply("handle_nat");
t_on_failure("missed_call");
}
if (!$avp(skip_relay) && !t_relay()) {
send_reply(500,"Internal Error");
}
exit;
}
branch_route[per_branch_ops] {
xlog("new branch at $ru\n");
}
onreply_route[handle_nat] {
xlog("incoming reply\n");
}
failure_route[missed_call] {
if (t_was_cancelled()) {
exit;
}
# uncomment the following lines if you want to block client
# redirect based on 3xx replies.
##if (t_check_status("3[0-9][0-9]")) {
##t_reply(404,"Not found");
## exit;
##}
}
event_route [E_UL_CONTACT_REFRESH]
{
xlog("L_INFO", "E_UL_CONTACT_REFRESH\n");
}
route [resume_route] {
if (is_method("BYE")) {
# do accounting even if the transaction fails
do_accounting("log","failed");
}
route(relay);
exit;
}
===================================================================================
startup log
===================================================================================
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/signaling.so
Jun 24 06:16:03 [196] DBG:core:register_module: register_pv: signaling
Jun 24 06:16:03 [196] DBG:core:pv_add_extra: extra items list is not
initialized
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 0
dependency signaling - (module tm)
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 0
dependency signaling - (module sl)
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/sl.so
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
Jun 24 06:16:03 [196] DBG:core:register_module: register_pv: tm
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: tm matches module tm
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <fr_timeout> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: tm matches module tm
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <fr_inv_timeout>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: tm matches module tm
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<restart_fr_on_each_reply> in module tm
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: tm matches module tm
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<onreply_avp_mode> in module tm
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/rr.so
Jun 24 06:16:03 [196] DBG:core:register_module: register_pv: rr
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: rr matches module rr
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <append_fromtag>
in module rr [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/maxfwd.so
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/sipmsgops.so
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/mi_fifo.so
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: mi_fifo matches module
mi_fifo
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <fifo_name> in
module mi_fifo [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: mi_fifo matches module
mi_fifo
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <fifo_mode> in
module mi_fifo [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/db_mysql.so
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/usrloc.so
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: usrloc matches module
usrloc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <nat_bflag> in
module usrloc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: usrloc matches module
usrloc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<working_mode_preset> in module usrloc
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:add_modparam_dependencies: adding modparam
dependencies:
Jun 24 06:16:03 [196] DBG:core:add_modparam_dependencies: dependency found:
usrloc ---> ( sqldb module (null) )
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency usrloc - (sqldb module (null))
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: usrloc matches module
usrloc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<contact_refresh_timer> in module usrloc
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/registrar.so
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency registrar - (module usrloc)
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency registrar - (module signaling)
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 0
dependency registrar - (module tm)
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: registrar matches
module registrar
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<tcp_persistent_flag> in module registrar
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: registrar matches
module registrar
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <pn_enable> in
module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:add_modparam_dependencies: adding modparam
dependencies:
Jun 24 06:16:03 [196] DBG:core:add_modparam_dependencies: dependency found:
registrar ---> ( module tm )
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency registrar - (module tm)
Jun 24 06:16:03 [196] DBG:core:add_modparam_dependencies: dependency found:
registrar ---> ( module event_routing )
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency registrar - (module event_routing)
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: registrar matches
module registrar
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <pn_providers> in
module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: registrar matches
module registrar
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <pn_enable_purr>
in module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: registrar matches
module registrar
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <min_expires> in
module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/acc.so
Jun 24 06:16:03 [196] DBG:core:register_module: register_pv: acc
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 2
dependency acc - (module tm)
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 0
dependency acc - (module dialog)
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: acc matches module acc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <early_media> in
module acc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: acc matches module acc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found <report_cancels>
in module acc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: acc matches module acc
Jun 24 06:16:03 [196] DBG:core:set_mod_param_regex: found
<detect_direction> in module acc
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/event_routing.so
Jun 24 06:16:03 [196] DBG:core:add_module_dependency: adding type 0
dependency event_routing - (module tm)
Jun 24 06:16:03 [196] DBG:core:load_module: loading module
/usr/lib/x86_64-linux-gnu/opensips/modules/event_route.so
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t:
<mf_process_maxfwd_header> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found
<mf_process_maxfwd_header> in module maxfwd
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <has_totag> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <has_totag> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_check_trans> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_check_trans>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_relay> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_relay> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <loose_route> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <loose_route>
in module rr [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_mod_acmd_export_t: found
<pn_process_purr> in module registrar
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_check_trans> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_check_trans>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_relay> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_relay> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_check_trans> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_check_trans>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: found <is_myself>
core function
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: found <is_myself>
core function
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <loose_route> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <loose_route>
in module rr [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <record_route> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <record_route>
in module rr [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <do_accounting> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <do_accounting>
in module acc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: found <is_myself>
core function
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <append_hf> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <append_hf> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <save> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <save> in
module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:__search_avp_map: looking for [skip_relay]
avp - found -1
Jun 24 06:16:03 [196] DBG:core:new_avp_alias: added alias skip_relay with
id 1
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <lookup> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <lookup> in
module registrar [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:__search_avp_map: looking for [skip_relay]
avp - found 1
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_reply> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_reply> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <do_accounting> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <do_accounting>
in module acc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_on_branch> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_on_branch>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_on_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_on_reply> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_on_failure> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_on_failure>
in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:__search_avp_map: looking for [skip_relay]
avp - found 1
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_relay> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <t_relay> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <send_reply> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <send_reply> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <t_was_cancelled>
not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found
<t_was_cancelled> in module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <is_method> not found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <is_method> in
module sipmsgops [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_core_cmd_export_t: <do_accounting> not
found
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <do_accounting>
in module acc [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency event_routing -> module tm
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency acc -> module dialog
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: module acc
soft-depends on module dialog, and it was not loaded -- proceeding
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency acc -> module tm
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency registrar -> module event_routing
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency registrar -> module tm
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency registrar -> module tm
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency registrar -> module signaling
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency registrar -> module usrloc
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency usrloc -> sqldb module
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency signaling -> module sl
Jun 24 06:16:03 [196] DBG:core:solve_module_dependencies: solving
dependency signaling -> module tm
Jun 24 06:16:03 [196] INFO:core:fix_poll_method: using epoll as the IO
watch method (auto detected)
Jun 24 06:16:03 [196] DBG:core:main: Loaded 1 transport protocols
Jun 24 06:16:03 [196] DBG:core:socket2str: <udp:10.0.2.208:5060>
Listening on
udp: 10.0.2.208 [10.0.2.208]:5060
Aliases:
udp: sip.mydomain.com:5060
udp: 10.0.2.208:5060
Jun 24 06:16:03 [196] DBG:core:create_status_pipe: created status pipe,
fds=[3, 4]
Jun 24 06:16:03 [196] NOTICE:core:main: DEBUG MODE activated
Jun 24 06:16:03 [196] NOTICE:core:main: setting UDP children to 2 (found 4)
Jun 24 06:16:03 [196] DBG:core:install_sigs: override SIGSEGV handler:
success
Jun 24 06:16:03 [196] DBG:core:set_core_dump: core dump limits set to
18446744073709551615
Jun 24 06:16:03 [196] NOTICE:core:main: version: opensips 3.1.2
(x86_64/linux)
Jun 24 06:16:03 [196] NOTICE:core:main: using 32 MB of shared memory,
allocator: F_MALLOC
Jun 24 06:16:03 [196] NOTICE:core:main: using 16 MB of private process
memory, allocator: F_MALLOC
Jun 24 06:16:03 [196] WARNING:core:init_reactor_size: shrinking reactor
size from 1048576 (autodetected via rlimit) to 41943 (limited by memory of
10% from 16Mb)
Jun 24 06:16:03 [196] WARNING:core:init_reactor_size: use
'open_files_limit' to enforce other limit or increase pkg memory
Jun 24 06:16:03 [196] INFO:core:init_reactor_size: reactor size 41943
(using up to 1.60Mb of memory per process)
Jun 24 06:16:03 [196] DBG:core:ipc_register_handler: IPC type 0 [RPC]
registered with handler (nil)
Jun 24 06:16:03 [196] DBG:core:__search_avp_map: looking for
[serial_branch] avp - found -1
Jun 24 06:16:03 [196] DBG:core:new_avp_alias: added alias serial_branch
with id 2
Jun 24 06:16:03 [196] DBG:core:find_mod_export: <trace_bind_api> in module
proto_hep not found
Jun 24 06:16:03 [196] DBG:core:trace_prot_bind: <proto_hep> has no bind api
function
Jun 24 06:16:03 [196] DBG:core:try_load_trace_api: No tracing module used!
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_CORE_THRESHOLD(0)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_CORE_SHM_THRESHOLD(1)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_CORE_PKG_THRESHOLD(2)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_CORE_PROC_AUTO_SCALE(3)>
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: <load_dlg> not found
Jun 24 06:16:03 [196] DBG:acc:mod_preinit: failed to load dialog API - is
the dialog module loaded?
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module tm
Jun 24 06:16:03 [196] INFO:tm:mod_init: TM - initializing...
Jun 24 06:16:03 [196] DBG:core:get_flag_id_by_name: Flag name is null!
Jun 24 06:16:03 [196] DBG:tm:init_callid: Call-ID initialization:
'6f6ca3702815f552'
Jun 24 06:16:03 [196] DBG:tm:lock_initialize: lock initialization started
Jun 24 06:16:03 [196] DBG:tm:tm_init_timers: creating 0 parallel timer
structures
Jun 24 06:16:03 [196] DBG:tm:mod_init: timer set shift is 3
Jun 24 06:16:03 [196] DBG:core:MD5StringArray: MD5 calculated:
020bb7acec0d52c399b40c59f5e1f126
Jun 24 06:16:03 [196] DBG:core:register_pv_context: Registered new context:
request / 0x7fc8b3a2dc00
Jun 24 06:16:03 [196] DBG:core:register_pv_context: Context not found
Jun 24 06:16:03 [196] DBG:core:register_pv_context: Registered new context:
reply / 0x7fc8b3a2c600
Jun 24 06:16:03 [196] DBG:core:register_pv_context: Context not found
Jun 24 06:16:03 [196] DBG:core:add_pv_context: Registered new context: reply
Jun 24 06:16:03 [196] DBG:core:__search_avp_map: looking for [uac_ctx] avp
- found -1
Jun 24 06:16:03 [196] DBG:core:new_avp_alias: added alias uac_ctx with id 3
Jun 24 06:16:03 [196] DBG:tm:tm_init_cluster: tm_replication_cluster not
set - not engaging!
Jun 24 06:16:03 [196] DBG:core:init_mod: registering stats for tm
Jun 24 06:16:03 [196] DBG:core:init_mod: register MI for tm
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module sl
Jun 24 06:16:03 [196] INFO:sl:mod_init: Initializing StateLess engine
Jun 24 06:16:03 [196] DBG:core:init_mod: registering stats for sl
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module signaling
Jun 24 06:16:03 [196] NOTICE:signaling:mod_init: initializing module ...
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_tm> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_sl> in
module sl [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module rr
Jun 24 06:16:03 [196] INFO:rr:mod_init: rr - initializing
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module maxfwd
Jun 24 06:16:03 [196] INFO:maxfwd:mod_init: initializing...
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module sipmsgops
Jun 24 06:16:03 [196] INFO:sipmsgops:mod_init: initializing...
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module mi_fifo
Jun 24 06:16:03 [196] DBG:mi_fifo:mi_mod_init: testing fifo existence ...
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module db_mysql
Jun 24 06:16:03 [196] DBG:db_mysql:mysql_mod_init: mysql: MySQL client
version is 10.3.29
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_MYSQL_CONNECTION(4)>
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module usrloc
Jun 24 06:16:03 [196] DBG:usrloc:mod_init: initializing
Jun 24 06:16:03 [196] INFO:usrloc:ul_init_locks: locks array size 512
Jun 24 06:16:03 [196] DBG:core:get_flag_id_by_name: New flag: [ NAT : 0 ][1]
Jun 24 06:16:03 [196] DBG:usrloc:ul_check_config: ul config: db_mode=-1,
cluster_mode=5, rrp=0, sql_wm=0
Jun 24 06:16:03 [196] DBG:core:find_mod_export: found <db_bind_api> in
module db_mysql [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:db_bind_mod: using db bind api for db_mysql
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_AOR_INSERT(5)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_AOR_DELETE(6)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_CONTACT_INSERT(7)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_CONTACT_UPDATE(8)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_CONTACT_DELETE(9)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_CONTACT_REFRESH(10)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_UL_LATENCY_UPDATE(11)>
Jun 24 06:16:03 [196] DBG:core:init_mod: registering stats for usrloc
Jun 24 06:16:03 [196] DBG:core:init_mod: register MI for usrloc
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module event_routing
Jun 24 06:16:03 [196] DBG:core:ipc_register_handler: IPC type 1 [EBR]
registered with handler 0x7fc8b2d3a9e0
Jun 24 06:16:03 [196] DBG:event_routing:mod_init: trying to load TM API, if
available
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_tm> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module registrar
Jun 24 06:16:03 [196] INFO:registrar:mod_init: initializing...
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_sig> in
module signaling [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_tm> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found
<ul_bind_usrloc> in module usrloc
[/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:get_flag_id_by_name: New flag: [
TCP_PERSISTENT : 0 ][0]
Jun 24 06:16:03 [196] DBG:core:is_mod_func_used: function record_route
found to be used in script
Jun 24 06:16:03 [196] DBG:core:is_mod_async_func_used: function
pn_process_purr found to be used in script
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <ebr_bind> in
module event_routing [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:event_routing:add_ebr_event: Adding new event
<E_UL_CONTACT_UPDATE>
Jun 24 06:16:03 [196] DBG:registrar:pn_init: parsed PN contact param:
'pn-provider'
Jun 24 06:16:03 [196] DBG:registrar:pn_init: parsed PN contact param:
'pn-prid'
Jun 24 06:16:03 [196] DBG:registrar:pn_init: parsed PN contact param:
'pn-param'
Jun 24 06:16:03 [196] DBG:registrar:pn_init: parsed PN provider: 'fcm',
hdr: 'Feature-Caps: +sip.pns="fcm";+sip.pnsreg="130";+sip.pnspurr="'
Jun 24 06:16:03 [196] DBG:core:init_mod: registering stats for registrar
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module acc
Jun 24 06:16:03 [196] INFO:acc:mod_init: initializing...
Jun 24 06:16:03 [196] DBG:core:find_mod_cmd_export_t: found <load_tm> in
module tm [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:find_mod_export: found <db_bind_api> in
module db_mysql [/usr/lib/x86_64-linux-gnu/opensips/modules/]
Jun 24 06:16:03 [196] DBG:core:db_bind_mod: using db bind api for db_mysql
Jun 24 06:16:03 [196] DBG:core:db_do_init: connection 0x7fc8b5a9fbd0 not
found in pool
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [196] DBG:core:db_do_init: connection 0x7fc8b5a9fbd0
inserted in pool as 0x7fc8b5a9fc48
Jun 24 06:16:03 [196] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:16:03 [196] DBG:core:db_new_result: allocate 48 bytes for result
set at 0x7fc8b5aa02d8
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_get_columns: 1 columns returned
from the query
Jun 24 06:16:03 [196] DBG:core:db_allocate_columns: allocate 28 bytes for
result columns at 0x7fc8b5aa1670
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7fc8b5aa1678)[0]=[table_version]
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:16:03 [196] DBG:core:db_allocate_rows: allocate 48 bytes for
result rows and values at 0x7fc8b5aa16c0
Jun 24 06:16:03 [196] DBG:db_mysql:db_mysql_str2val: converting INT [7]
Jun 24 06:16:03 [196] DBG:core:db_free_columns: freeing result columns at
0x7fc8b5aa1670
Jun 24 06:16:03 [196] DBG:core:db_free_rows: freeing 1 rows
Jun 24 06:16:03 [196] DBG:core:db_free_row: freeing row values at
0x7fc8b5aa16d0
Jun 24 06:16:03 [196] DBG:core:db_free_rows: freeing rows at 0x7fc8b5aa16c0
Jun 24 06:16:03 [196] DBG:core:db_free_result: freeing result set at
0x7fc8b5aa02d8
Jun 24 06:16:03 [196] DBG:core:pool_remove: removing connection from the
pool
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_ACC_EVENT(12)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_ACC_CDR(13)>
Jun 24 06:16:03 [196] INFO:core:evi_publish_event: Registered event
<E_ACC_MISSED_EVENT(14)>
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module event_route
Jun 24 06:16:03 [196] NOTICE:event_route:mod_init: initializing module ...
Jun 24 06:16:03 [196] DBG:core:init_mod: initializing module proto_udp
Jun 24 06:16:03 [196] INFO:core:mod_init: initializing UDP-plain protocol
Jun 24 06:16:03 [196] DBG:core:buf_init: initializing...
Jun 24 06:16:03 [196] DBG:core:find_mod_export: <trace_bind_api> in module
proto_hep not found
Jun 24 06:16:03 [196] DBG:core:trace_prot_bind: <proto_hep> has no bind api
function
Jun 24 06:16:03 [196] DBG:core:init_xlog: failed to load trace protocol!
Jun 24 06:16:03 [196] DBG:core:count_module_procs: modules require 1 extra
processes
Jun 24 06:16:03 [-1] DBG:core:init_pkg_stats: setting stats for 9 processes
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing
mf_process_maxfwd_header, /etc/opensips/opensips.cfg:101
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:102
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing has_totag,
/etc/opensips/opensips.cfg:106
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:109
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x4
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[ACK/4]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_check_trans,
/etc/opensips/opensips.cfg:109
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_relay,
/etc/opensips/opensips.cfg:110
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing loose_route,
/etc/opensips/opensips.cfg:116
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:119
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:123
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x4
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[ACK/4]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing async pn_process_purr,
/etc/opensips/opensips.cfg:124
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:134
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x2
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[CANCEL/2]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_check_trans,
/etc/opensips/opensips.cfg:135
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_relay,
/etc/opensips/opensips.cfg:136
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_check_trans,
/etc/opensips/opensips.cfg:141
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:143
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x80
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[REGISTER/128]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_myself,
/etc/opensips/opensips.cfg:145
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_myself,
/etc/opensips/opensips.cfg:150
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:151
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing loose_route,
/etc/opensips/opensips.cfg:159
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:162
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x4
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[ACK/4]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:163
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:168
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x180
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for methods
[REGISTER,MESSAGE/384]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing record_route,
/etc/opensips/opensips.cfg:169
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:172
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x1
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[INVITE/1]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing do_accounting,
/etc/opensips/opensips.cfg:174
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_myself,
/etc/opensips/opensips.cfg:178
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing append_hf,
/etc/opensips/opensips.cfg:179
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:186
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x2200
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for methods
[PUBLISH,SUBSCRIBE/8704]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:187
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:191
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x80
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[REGISTER/128]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing save,
/etc/opensips/opensips.cfg:193
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:201
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing lookup,
/etc/opensips/opensips.cfg:213
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_reply,
/etc/opensips/opensips.cfg:222
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing do_accounting,
/etc/opensips/opensips.cfg:227
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:281
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x8
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[BYE/8]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing do_accounting,
/etc/opensips/opensips.cfg:283
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing is_method,
/etc/opensips/opensips.cfg:234
Jun 24 06:16:03 [196] DBG:core:parse_methods: methods 0x1
Jun 24 06:16:03 [196] DBG:sipmsgops:fixup_method: using id for method
[INVITE/1]
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_on_branch,
/etc/opensips/opensips.cfg:235
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_on_reply,
/etc/opensips/opensips.cfg:236
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_on_failure,
/etc/opensips/opensips.cfg:237
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_relay,
/etc/opensips/opensips.cfg:240
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing send_reply,
/etc/opensips/opensips.cfg:241
Jun 24 06:16:03 [196] DBG:core:fix_actions: fixing t_was_cancelled,
/etc/opensips/opensips.cfg:260
Jun 24 06:16:03 [196] DBG:core:probe_max_sock_buff: getsockopt: rcv is
initially 212992
Jun 24 06:16:03 [196] DBG:core:probe_max_sock_buff: using rcv buffer of 416
kb
Jun 24 06:16:03 [196] DBG:core:start_module_procs: forking process "MI
FIFO"/0 for module mi_fifo
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "MI FIFO"
on slot 1
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process
"time_keeper" on slot 2
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "timer"
on slot 3
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "UDP
receiver" on slot 4
Jun 24 06:16:03 [197] DBG:core:init_mod_child: type=PROC_MODULE, rank=-2,
module=tm
Jun 24 06:16:03 [197] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-197 at 10.0.2.208'
Jun 24 06:16:03 [197] DBG:core:init_mod_child: type=PROC_MODULE, rank=-2,
module=usrloc
Jun 24 06:16:03 [197] DBG:core:init_mod_child: type=PROC_MODULE, rank=-2,
module=registrar
Jun 24 06:16:03 [197] DBG:core:init_mod_child: type=PROC_MODULE, rank=-2,
module=acc
Jun 24 06:16:03 [197] DBG:core:db_do_init: connection 0x7fc8b5a9c9d8 not
found in pool
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "UDP
receiver" on slot 5
Jun 24 06:16:03 [197] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "UDP
receiver" on slot 6
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "UDP
receiver" on slot 7
Jun 24 06:16:03 [196] DBG:core:internal_fork: forking new process "Timer
handler" on slot 8
Jun 24 06:16:03 [198] DBG:core:run_timer_process_jif: tv = 0, 10000 , m=10,
mu=10
Jun 24 06:16:03 [202] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(5 on 47) (0x55bd331b7500, 5, 1, (nil),1), fd_no=0/41943
Jun 24 06:16:03 [202] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(34 on 47) (0x55bd331b7500, 34, 4, (nil),1), fd_no=1/41943
Jun 24 06:16:03 [202] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(7 on 47) (0x55bd331b7500, 7, 4, (nil),1), fd_no=2/41943
Jun 24 06:16:03 [202] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(46 on 47) (0x55bd331b7500, 46, 17, 0x7fc8b5a8dcf8,1), fd_no=3/41943
Jun 24 06:16:03 [202] DBG:core:init_mod_child: type=CHILD, rank=3, module=tm
Jun 24 06:16:03 [202] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-202 at 10.0.2.208'
Jun 24 06:16:03 [202] DBG:core:init_mod_child: type=CHILD, rank=3,
module=usrloc
Jun 24 06:16:03 [202] DBG:core:db_do_init: connection 0x7fc8b5cdb220 not
found in pool
Jun 24 06:16:03 [202] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [204] DBG:core:io_watch_add: [Timer_extra] io_watch_add op
(42 on 47) (0x55bd331b7500, 42, 4, (nil),1), fd_no=0/41943
Jun 24 06:16:03 [204] DBG:core:io_watch_add: [Timer_extra] io_watch_add op
(5 on 47) (0x55bd331b7500, 5, 1, (nil),1), fd_no=1/41943
Jun 24 06:16:03 [204] DBG:core:init_mod_child: type=CHILD, rank=5, module=tm
Jun 24 06:16:03 [204] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-204 at 10.0.2.208'
Jun 24 06:16:03 [204] DBG:core:init_mod_child: type=CHILD, rank=5,
module=usrloc
Jun 24 06:16:03 [204] DBG:core:db_do_init: connection 0x7fc8b5cdb220 not
found in pool
Jun 24 06:16:03 [204] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [199] DBG:core:run_timer_process: tv = 0, 100000 , m=10
Jun 24 06:16:03 [201] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(5 on 47) (0x55bd331b7500, 5, 1, (nil),1), fd_no=0/41943
Jun 24 06:16:03 [201] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(30 on 47) (0x55bd331b7500, 30, 4, (nil),1), fd_no=1/41943
Jun 24 06:16:03 [203] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(5 on 47) (0x55bd331b7500, 5, 1, (nil),1), fd_no=0/41943
Jun 24 06:16:03 [200] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(5 on 47) (0x55bd331b7500, 5, 1, (nil),1), fd_no=0/41943
Jun 24 06:16:03 [201] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(7 on 47) (0x55bd331b7500, 7, 4, (nil),1), fd_no=2/41943
Jun 24 06:16:03 [201] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(46 on 47) (0x55bd331b7500, 46, 17, 0x7fc8b5a8dcf8,1), fd_no=3/41943
Jun 24 06:16:03 [201] DBG:core:init_mod_child: type=CHILD, rank=2, module=tm
Jun 24 06:16:03 [203] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(38 on 47) (0x55bd331b7500, 38, 4, (nil),1), fd_no=1/41943
Jun 24 06:16:03 [201] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-201 at 10.0.2.208'
Jun 24 06:16:03 [201] DBG:core:init_mod_child: type=CHILD, rank=2,
module=usrloc
Jun 24 06:16:03 [201] DBG:core:db_do_init: connection 0x7fc8b5cdb220 not
found in pool
Jun 24 06:16:03 [203] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(7 on 47) (0x55bd331b7500, 7, 4, (nil),1), fd_no=2/41943
Jun 24 06:16:03 [200] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(26 on 47) (0x55bd331b7500, 26, 4, (nil),1), fd_no=1/41943
Jun 24 06:16:03 [201] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [203] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(46 on 47) (0x55bd331b7500, 46, 17, 0x7fc8b5a8dcf8,1), fd_no=3/41943
Jun 24 06:16:03 [197] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [200] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(7 on 47) (0x55bd331b7500, 7, 4, (nil),1), fd_no=2/41943
Jun 24 06:16:03 [197] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [197] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [197] DBG:core:db_do_init: connection 0x7fc8b5a9c9d8
inserted in pool as 0x7fc8b5a9ad40
Jun 24 06:16:03 [197] DBG:core:init_mod_child: type=PROC_MODULE, rank=-2,
module=event_route
Jun 24 06:16:03 [197] DBG:mi_fifo:fifo_process: new process with pid = 197
created
Jun 24 06:16:03 [197] DBG:mi_fifo:mi_create_fifo: FIFO created @
/tmp/opensips_fifo
Jun 24 06:16:03 [197] DBG:mi_fifo:mi_create_fifo: fifo /tmp/opensips_fifo
opened, mode=666
Jun 24 06:16:03 [197] DBG:core:db_do_init: connection 0x7fc8b5a9a9a8 found
in pool as 0x7fc8b5a9ad40
Jun 24 06:16:03 [203] DBG:core:init_mod_child: type=CHILD, rank=4, module=tm
Jun 24 06:16:03 [203] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-203 at 10.0.2.208'
Jun 24 06:16:03 [203] DBG:core:init_mod_child: type=CHILD, rank=4,
module=usrloc
Jun 24 06:16:03 [203] DBG:core:db_do_init: connection 0x7fc8b5cdb220 not
found in pool
Jun 24 06:16:03 [203] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [200] DBG:core:io_watch_add: [UDP_worker] io_watch_add op
(46 on 47) (0x55bd331b7500, 46, 17, 0x7fc8b5a8dcf8,1), fd_no=3/41943
Jun 24 06:16:03 [200] DBG:core:init_mod_child: type=CHILD, rank=1, module=tm
Jun 24 06:16:03 [200] DBG:tm:child_init_callid: callid: '
6f6ca3702815f552-200 at 10.0.2.208'
Jun 24 06:16:03 [200] DBG:core:init_mod_child: type=CHILD, rank=1,
module=usrloc
Jun 24 06:16:03 [200] DBG:core:db_do_init: connection 0x7fc8b5cdb220 not
found in pool
Jun 24 06:16:03 [200] DBG:db_mysql:db_mysql_connect: opening connection:
mysql://xxxx:xxxx@127.0.0.1/opensips
Jun 24 06:16:03 [202] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [202] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [202] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [202] DBG:core:db_do_init: connection 0x7fc8b5cdb220
inserted in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [202] DBG:core:init_mod_child: type=CHILD, rank=3,
module=registrar
Jun 24 06:16:03 [202] DBG:core:init_mod_child: type=CHILD, rank=3,
module=acc
Jun 24 06:16:03 [202] DBG:core:db_do_init: connection 0x7fc8b5cdbb18 found
in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [204] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [204] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [204] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [204] DBG:core:db_do_init: connection 0x7fc8b5cdb220
inserted in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [204] DBG:core:init_mod_child: type=CHILD, rank=5,
module=registrar
Jun 24 06:16:03 [204] DBG:core:init_mod_child: type=CHILD, rank=5,
module=acc
Jun 24 06:16:03 [204] DBG:core:db_do_init: connection 0x7fc8b5cdbb18 found
in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [204] DBG:core:init_mod_child: type=CHILD, rank=5,
module=event_route
Jun 24 06:16:03 [202] DBG:core:init_mod_child: type=CHILD, rank=3,
module=event_route
Jun 24 06:16:03 [201] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [201] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [201] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [201] DBG:core:db_do_init: connection 0x7fc8b5cdb220
inserted in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [201] DBG:core:init_mod_child: type=CHILD, rank=2,
module=registrar
Jun 24 06:16:03 [201] DBG:core:init_mod_child: type=CHILD, rank=2,
module=acc
Jun 24 06:16:03 [201] DBG:core:db_do_init: connection 0x7fc8b5cdbb18 found
in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [201] DBG:core:init_mod_child: type=CHILD, rank=2,
module=event_route
Jun 24 06:16:03 [203] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [203] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [203] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [203] DBG:core:db_do_init: connection 0x7fc8b5cdb220
inserted in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [203] DBG:core:init_mod_child: type=CHILD, rank=4,
module=registrar
Jun 24 06:16:03 [203] DBG:core:init_mod_child: type=CHILD, rank=4,
module=acc
Jun 24 06:16:03 [203] DBG:core:db_do_init: connection 0x7fc8b5cdbb18 found
in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [203] DBG:core:init_mod_child: type=CHILD, rank=4,
module=event_route
Jun 24 06:16:03 [200] DBG:db_mysql:db_mysql_connect: connection type is
127.0.0.1 via TCP/IP
Jun 24 06:16:03 [200] DBG:db_mysql:db_mysql_connect: protocol version is 10
Jun 24 06:16:03 [200] DBG:db_mysql:db_mysql_connect: server version is
5.7.33-google-log
Jun 24 06:16:03 [200] DBG:core:db_do_init: connection 0x7fc8b5cdb220
inserted in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [200] DBG:core:init_mod_child: type=CHILD, rank=1,
module=registrar
Jun 24 06:16:03 [200] DBG:core:init_mod_child: type=CHILD, rank=1,
module=acc
Jun 24 06:16:03 [200] DBG:core:db_do_init: connection 0x7fc8b5cdbb18 found
in pool as 0x7fc8b5cdb3d8
Jun 24 06:16:03 [200] DBG:core:init_mod_child: type=CHILD, rank=1,
module=event_route
Jun 24 06:16:03 [200] DBG:event_route:child_init: Registering event
E_UL_CONTACT_REFRESH
Jun 24 06:16:03 [200] DBG:event_route:scriptroute_parse: route is
<E_UL_CONTACT_REFRESH> idx 1
Jun 24 06:16:03 [200] DBG:core:evi_event_subscribe: added new subscriber
for event 10
===================================================================================
register request log
===================================================================================
Jun 24 06:18:07 [212] DBG:core:parse_msg: SIP Request:
Jun 24 06:18:07 [212] DBG:core:parse_msg: method: <REGISTER>
Jun 24 06:18:07 [212] DBG:core:parse_msg: uri: <sip:sip.mydomain.com>
Jun 24 06:18:07 [212] DBG:core:parse_msg: version: <SIP/2.0>
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK.3xtl2uq~l>; state=6
Jun 24 06:18:07 [212] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jun 24 06:18:07 [212] DBG:core:parse_via: end of header reached, state=5
Jun 24 06:18:07 [212] DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:parse_headers: this is the first via
Jun 24 06:18:07 [212] DBG:core:_parse_to: end of header reached, state=9
Jun 24 06:18:07 [212] DBG:core:_parse_to: display={}, ruri={
sip:user1 at sip.mydomain.com}
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: <To> [39]; uri=[
sip:user1 at sip.mydomain.com]
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: to body [
sip:user1 at sip.mydomain.com
]
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: cseq <CSeq>: <20> <REGISTER>
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: found end of header
Jun 24 06:18:07 [212] DBG:core:receive_msg: After parse_msg...
Jun 24 06:18:07 [212] DBG:core:receive_msg: preparing to run routing
scripts...
Jun 24 06:18:07 [212] DBG:maxfwd:is_maxfwd_present: value = 70
Jun 24 06:18:07 [212] DBG:sipmsgops:has_totag: no totag
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=78
Jun 24 06:18:07 [212] DBG:tm:t_lookup_request: start searching: hash=51128,
isACK=0
Jun 24 06:18:07 [212] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jun 24 06:18:07 [212] DBG:tm:t_lookup_request: no transaction found
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=200
Jun 24 06:18:07 [212] DBG:rr:find_first_route: No Route headers found
Jun 24 06:18:07 [212] DBG:rr:loose_route: There is no Route HF
Jun 24 06:18:07 [212] DBG:core:grep_sock_info_ext: checking if host==us:
27==10 && [sip.mydomain.com] == [10.0.2.208]
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:parse_params: Parsing params
for:[+sip.instance="<urn:uuid:8e9c71c9-9279-00c5-99fe-c0f80d147511>"]
Jun 24 06:18:07 [212] DBG:registrar:pn_inspect_request: skip PN processing,
matching mode already enforced
Jun 24 06:18:07 [212] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [212] DBG:core:db_new_result: allocate 48 bytes for result
set at 0x7f3279067500
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: 17 columns
returned from the query
Jun 24 06:18:07 [212] DBG:core:db_allocate_columns: allocate 476 bytes for
result columns at 0x7f3279067560
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790675e8)[0]=[contact_id]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_BIGINT
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790675f8)[1]=[contact]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067608)[2]=[expires]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067618)[3]=[q]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_DOUBLE
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067628)[4]=[callid]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067638)[5]=[cseq]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067648)[6]=[flags]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067658)[7]=[cflags]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067668)[8]=[user_agent]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067678)[9]=[received]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067688)[10]=[path]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067698)[11]=[socket]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790676a8)[12]=[methods]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790676b8)[13]=[last_modified]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_DATETIME
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790676c8)[14]=[sip_instance]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790676d8)[15]=[kv_store]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result
type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790676e8)[16]=[attr]
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_convert_rows: no rows returned
from the query
Jun 24 06:18:07 [212] DBG:usrloc:db_load_urecord: aor user1 not found in
table location
Jun 24 06:18:07 [212] DBG:core:db_free_columns: freeing result columns at
0x7f3279067560
Jun 24 06:18:07 [212] DBG:core:db_free_rows: freeing 0 rows
Jun 24 06:18:07 [212] DBG:core:db_free_result: freeing result set at
0x7f3279067500
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=8000000
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str domain='location'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str aor='user1'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str
uri='sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str received=''
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str path=''
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set int qval=-1
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str user_agent='Unknown
(belle-sip/4.3.0)'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str socket='udp:
10.0.2.208:5060'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set int bflags=0
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set int expires=1624515787
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str callid='HG8td6g-yW'
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set int cseq=20
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str attr=''
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set int latency=0
Jun 24 06:18:07 [212] DBG:core:evi_param_set: set str shtag=''
Jun 24 06:18:07 [212] DBG:core:get_dummy_sip_msg: allocating new sip msg
Jun 24 06:18:07 [212] DBG:core:parse_msg: SIP Request:
Jun 24 06:18:07 [212] DBG:core:parse_msg: method: <DUMMY>
Jun 24 06:18:07 [212] DBG:core:parse_msg: uri: <sip:user at dummy.com>
Jun 24 06:18:07 [212] DBG:core:parse_msg: version: <SIP/2.0>
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bKdummy>; state=16
Jun 24 06:18:07 [212] DBG:core:parse_via: end of header reached, state=5
Jun 24 06:18:07 [212] DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:parse_headers: this is the first via
Jun 24 06:18:07 [212] DBG:core:_parse_to: end of header reached, state=10
Jun 24 06:18:07 [212] DBG:core:_parse_to: display={}, ruri={sip:to at dummy.com
}
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: <To> [20]; uri=[
sip:to at dummy.com]
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: to body [<sip:to at dummy.com>
]
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: cseq <CSeq>: <1> <DUMMY>
Jun 24 06:18:07 [212] DBG:core:get_hdr_field: found end of header
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:get_dummy_sip_msg: setting as static to
0x7f3279067770
Jun 24 06:18:07 [212] DBG:core:release_dummy_sip_msg: cleaning the static
sip msg 0x7f3279067770
Jun 24 06:18:07 [212] DBG:core:destroy_avp_list: destroying list (nil)
Jun 24 06:18:07 [212] DBG:registrar:pn_add_reply_purr: no need to add
+sip.pnspurr for 'fcm'
Jun 24 06:18:07 [212] DBG:registrar:build_contact: created Contact HF:
Contact: <sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp>;expires=300
Jun 24 06:18:07 [212] DBG:usrloc:db_insert_ucontact: zero map size
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x7f3279065170 (tail=139854755550168) MC=0x7f3279065470
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_do_prepared_query: new
query=|insert into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,kv_store,attr
) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)|
Jun 24 06:18:07 [212] DBG:db_mysql:re_init_statement: query is <insert
into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,kv_store,attr
) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)>, ptr=(nil)
Jun 24 06:18:07 [212] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_do_prepared_query: new
statement(0x7f32790688b0) on connection: (0x7f3279065170) 0x7f32790653d8
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (0): len=5;
type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=254; type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (2): len=4;
type=3; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (3): len=8;
type=5; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=10; type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (5): len=4;
type=3; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (6): len=4;
type=3; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (7): len=0;
type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=25; type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=19; type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=40; type=12; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_val2bind: added val (14):
len=47; type=254; is_null=0
Jun 24 06:18:07 [212] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Jun 24 06:18:07 [212] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [212] DBG:core:MD5StringArray: MD5 calculated:
651a3aa6bda257b01dde8bf25e217bdd
Jun 24 06:18:07 [212] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [212] DBG:core:destroy_avp_list: destroying list (nil)
Jun 24 06:18:07 [212] DBG:core:receive_msg: cleaning up
Jun 24 06:18:07 [209] DBG:core:parse_msg: SIP Request:
Jun 24 06:18:07 [209] DBG:core:parse_msg: method: <REGISTER>
Jun 24 06:18:07 [209] DBG:core:parse_msg: uri: <sip:sip.mydomain.com>
Jun 24 06:18:07 [209] DBG:core:parse_msg: version: <SIP/2.0>
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [209] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK.fTP4rkt1q>; state=6
Jun 24 06:18:07 [209] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jun 24 06:18:07 [209] DBG:core:parse_via: end of header reached, state=5
Jun 24 06:18:07 [209] DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Jun 24 06:18:07 [209] DBG:core:parse_headers: this is the first via
Jun 24 06:18:07 [209] DBG:core:_parse_to: end of header reached, state=9
Jun 24 06:18:07 [209] DBG:core:_parse_to: display={}, ruri={
sip:user1 at sip.mydomain.com}
Jun 24 06:18:07 [209] DBG:core:get_hdr_field: <To> [39]; uri=[
sip:user1 at sip.mydomain.com]
Jun 24 06:18:07 [209] DBG:core:get_hdr_field: to body [
sip:user1 at sip.mydomain.com
]
Jun 24 06:18:07 [209] DBG:core:get_hdr_field: cseq <CSeq>: <21> <REGISTER>
Jun 24 06:18:07 [209] DBG:core:get_hdr_field: found end of header
Jun 24 06:18:07 [209] DBG:core:receive_msg: After parse_msg...
Jun 24 06:18:07 [209] DBG:core:receive_msg: preparing to run routing
scripts...
Jun 24 06:18:07 [209] DBG:maxfwd:is_maxfwd_present: value = 70
Jun 24 06:18:07 [209] DBG:sipmsgops:has_totag: no totag
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=78
Jun 24 06:18:07 [209] DBG:tm:t_lookup_request: start searching: hash=51129,
isACK=0
Jun 24 06:18:07 [209] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jun 24 06:18:07 [209] DBG:tm:t_lookup_request: no transaction found
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=200
Jun 24 06:18:07 [209] DBG:rr:find_first_route: No Route headers found
Jun 24 06:18:07 [209] DBG:rr:loose_route: There is no Route HF
Jun 24 06:18:07 [209] DBG:core:grep_sock_info_ext: checking if host==us:
27==10 && [sip.mydomain.com] == [10.0.2.208]
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [209] DBG:core:parse_params: Parsing params
for:[+sip.instance="<urn:uuid:8e9c71c9-9279-00c5-99fe-c0f80d147511>"]
Jun 24 06:18:07 [209] DBG:registrar:pn_inspect_request: skip PN processing,
matching mode already enforced
Jun 24 06:18:07 [209] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [209] DBG:core:db_new_result: allocate 48 bytes for result
set at 0x7f3279067470
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: 17 columns
returned from the query
Jun 24 06:18:07 [209] DBG:core:db_allocate_columns: allocate 476 bytes for
result columns at 0x7f3279067680
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067708)[0]=[contact_id]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_BIGINT
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067718)[1]=[contact]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067728)[2]=[expires]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067738)[3]=[q]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_DOUBLE
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067748)[4]=[callid]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067758)[5]=[cseq]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067768)[6]=[flags]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067778)[7]=[cflags]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067788)[8]=[user_agent]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067798)[9]=[received]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677a8)[10]=[path]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677b8)[11]=[socket]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677c8)[12]=[methods]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_INT result
type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677d8)[13]=[last_modified]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_DATETIME
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677e8)[14]=[sip_instance]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f32790677f8)[15]=[kv_store]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result
type
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f3279067808)[16]=[attr]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Jun 24 06:18:07 [209] DBG:core:db_allocate_rows: allocate 560 bytes for
result rows and values at 0x7f3279068b28
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting INT
BIG[4189995556047270793]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING
[sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting INT
[1624515787]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting DOUBLE
[-1.00]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING
[HG8td6g-yW]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting INT [20]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting INT [0]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING []
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING
[Unknown (belle-sip/4.3.0)]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING [udp:
10.0.2.208:5060]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting DATETIME
[2021-06-24 06:18:07]
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_str2val: converting STRING
[<urn:uuid:8e9c71c9-9279-00c5-99fe-c0f80d147511>]
Jun 24 06:18:07 [209] DBG:usrloc:dbrow2info: flag str: ''
Jun 24 06:18:07 [209] DBG:usrloc:dbrow2info: set flags: 0
Jun 24 06:18:07 [209] DBG:core:grep_sock_info_ext: checking if host==us:
10==10 && [10.0.2.208] == [10.0.2.208]
Jun 24 06:18:07 [209] DBG:core:grep_sock_info_ext: checking if port 5060
matches port 5060
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str domain='location'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str aor='user1'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str
uri='sip:user1 at 192.168.31.223:59600
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str received=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str path=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int qval=-1
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str user_agent='Unknown
(belle-sip/4.3.0)'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str socket='udp:
10.0.2.208:5060'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int bflags=0
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int expires=1624515787
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str callid='HG8td6g-yW'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int cseq=20
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str attr=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int latency=0
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str shtag=''
Jun 24 06:18:07 [209] DBG:core:get_dummy_sip_msg: reusing the static sip
msg 0x7f32790678e0
Jun 24 06:18:07 [209] DBG:core:release_dummy_sip_msg: cleaning the static
sip msg 0x7f32790678e0
Jun 24 06:18:07 [209] DBG:core:destroy_avp_list: destroying list (nil)
Jun 24 06:18:07 [209] DBG:core:db_free_columns: freeing result columns at
0x7f3279067680
Jun 24 06:18:07 [209] DBG:core:db_free_rows: freeing 1 rows
Jun 24 06:18:07 [209] DBG:core:db_free_row: freeing row values at
0x7f3279068b38
Jun 24 06:18:07 [209] DBG:core:db_free_rows: freeing rows at 0x7f3279068b28
Jun 24 06:18:07 [209] DBG:core:db_free_result: freeing result set at
0x7f3279067470
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=8000000
Jun 24 06:18:07 [209] DBG:usrloc:get_ucontact: using ct matching mode 0
Jun 24 06:18:07 [209] DBG:usrloc:get_ucontact: failed to match any existing
contacts
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str domain='location'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str aor='user1'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str
uri='sip:user1 at 10.0.2.90:60730
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str received=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str path=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int qval=-1
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str user_agent='Unknown
(belle-sip/4.3.0)'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str socket='udp:
10.0.2.208:5060'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int bflags=0
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int expires=1624515787
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str callid='HG8td6g-yW'
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int cseq=21
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str attr=''
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set int latency=0
Jun 24 06:18:07 [209] DBG:core:evi_param_set: set str shtag=''
Jun 24 06:18:07 [209] DBG:core:get_dummy_sip_msg: reusing the static sip
msg 0x7f32790678e0
Jun 24 06:18:07 [209] DBG:core:release_dummy_sip_msg: cleaning the static
sip msg 0x7f32790678e0
Jun 24 06:18:07 [209] DBG:core:destroy_avp_list: destroying list (nil)
Jun 24 06:18:07 [209] DBG:registrar:pn_add_reply_purr: no need to add
+sip.pnspurr for 'fcm'
Jun 24 06:18:07 [209] DBG:registrar:build_contact: created Contact HF:
Contact: <sip:user1 at 192.168.31.223:59600;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp>;expires=300,
<sip:user1 at 10.0.2.90:60730
;pn-provider=fcm;pn-param=***;pn-prid=***;transport=udp>;expires=300
Jun 24 06:18:07 [209] DBG:usrloc:db_insert_ucontact: zero map size
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x7f3279065170 (tail=139854755550168) MC=0x7f3279065470
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_do_prepared_query: new
query=|insert into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,kv_store,attr
) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)|
Jun 24 06:18:07 [209] DBG:db_mysql:re_init_statement: query is <insert
into location
(username,contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,sip_instance,kv_store,attr
) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)>, ptr=(nil)
Jun 24 06:18:07 [209] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_do_prepared_query: new
statement(0x7f3279069000) on connection: (0x7f3279065170) 0x7f32790653d8
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_do_prepared_query: set values
for the statement run
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (0): len=5;
type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=249; type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (2): len=4;
type=3; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (3): len=8;
type=5; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (4):
len=10; type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (5): len=4;
type=3; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (6): len=4;
type=3; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (7): len=0;
type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (8):
len=25; type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (11):
len=19; type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (13):
len=40; type=12; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_val2bind: added val (14):
len=47; type=254; is_null=0
Jun 24 06:18:07 [209] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Jun 24 06:18:07 [209] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [209] DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
Jun 24 06:18:07 [209] DBG:core:MD5StringArray: MD5 calculated:
dfa41a9b0abf079682247285be03936f
Jun 24 06:18:07 [209] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 24 06:18:07 [209] DBG:core:destroy_avp_list: destroying list (nil)
Jun 24 06:18:07 [209] DBG:core:receive_msg: cleaning up
===================================================================================
database location table
[image: location.PNG]
I already have pn-provide, pn-param and pn-prid but why the flags are still
0?
Does the problem occur here?
DBG:registrar:pn_inspect_request: skip PN processing, matching mode already
enforced
I don’t know why PN processing was skipped, where can I solve the problem?
Thanks!
This is the original question link
<https://github.com/OpenSIPS/opensips/issues/2556>.
===================================================================================
google kubernates engine: 1.17.17-gke.4900
opensips: 3.1
android: 6.0.1
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20210624/7a673132/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: location.PNG
Type: image/png
Size: 16871 bytes
Desc: not available
URL: <http://lists.opensips.org/pipermail/users/attachments/20210624/7a673132/attachment-0001.png>
More information about the Users
mailing list