dialog.so: dialog don't finished with BYE

Hi,
I use Opensips 1.4.4-notls and have problem with module dialog.so. To documentation it is written that "The

dialog is automatically destroyed when a “BYE” is received" But dialog don't destroyed! :( It continues to

exist, While not to be deleted by default timeout.

Config:

[skip]
loadmodule "dialog.so"        #Dialog support module
[skip]
modparam("dialog", "dlg_flag", 4)
modparam("dialog", "default_timeout", 3600)
modparam("dialog", "dlg_match_mode", 1)
modparam("dialog", "db_mode", 2)
modparam("dialog", "db_update_period", 60)
modparam("dialog", "profiles_with_value", "calls")
[skip]

route{
    if (!is_method("REGISTER|OPTIONS")) {
        xlog("L_WARN","SCRIPT: Record route enable for URI: $fu\n");
        record_route();
    };

    [skip]

    if (is_method("INVITE")) {
        xlog("L_WARN","SCRIPT: INVITE method from URI:$fu processed\n");
        route(7);
        return;
    };

    [skip]

    if (is_method("BYE|ACK|INFO|CANCEL")) {
        xlog("L_WARN", "SCRIPT: $rm method from URI:$fu processed\n");
        if (!t_relay()) {
            xlog("L_WARN", "SCRIPT: Failure route method $rm from URI:$fu to $ru \n");
            sl_reply_error();
        };
        return;
    };
   
    [skip]
}

[skip]

route[7] {
   
    [skip]

    setflag(4);
   
    if (isflagset(12)) {
        set_dlg_profile("calls", "$rU")
        xlog("L_WARN", "SCRIPT: Incomming call. Add $rU to dialog profile \n");
    } else {
        set_dlg_profile("calls", "$fU");
        xlog("L_WARN", "SCRIPT: Outcomming call. Add $fU to dialog profile \n");
    }

    if (!t_relay()) {
        xlog("L_WARN", "SCRIPT: Failure route from URI:$fu to $fu \n");
        sl_reply_error();
    };
}

debug:

sips# opensips
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/db_mysql.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/sl.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/tm.so
Jan 20 14:38:59 [53020] DBG:core:register_module: register_pv: tm
Jan 20 14:38:59 [53020] DBG:core:pv_add_extra: extra items list is not initialized
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/rr.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/maxfwd.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/usrloc.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/registrar.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/textops.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/mi_fifo.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/uri_db.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/uri.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/xlog.so
Jan 20 14:38:59 [53020] DBG:core:register_module: register_pv: xlog
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/acc.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/auth.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/auth_db.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/group.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/avpops.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/options.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/uac.so
Jan 20 14:38:59 [53020] DBG:core:yyparse: loading module /usr/local/lib/opensips/modules/dialog.so
Jan 20 14:38:59 [53020] DBG:core:register_module: register_pv: dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module group
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module group [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module auth_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module auth_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module uri_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module uri_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc|auth_db|group|uri_db|usrloc|dialog matches module usrloc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_url> in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db|group|uri_db|usrloc matches module group
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <use_domain> in module group [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db|group|uri_db|usrloc matches module auth_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <use_domain> in module auth_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db|group|uri_db|usrloc matches module uri_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <use_domain> in module uri_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db|group|uri_db|usrloc matches module usrloc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <use_domain> in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: mi_fifo matches module mi_fifo
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <fifo_name> in module mi_fifo [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: mi_fifo matches module mi_fifo
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <fifo_mode> in module mi_fifo [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: rr matches module rr
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <enable_full_lr> in module rr [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: registrar matches module registrar
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <method_filtering> in module registrar [/usr/local/lib/opensips/modules]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: registrar matches module registrar
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <append_branches> in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: registrar matches module registrar
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <min_expires> in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: registrar matches module registrar
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <max_expires> in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: registrar matches module registrar
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <default_expires> in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: uri_db matches module uri_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <use_uri_table> in module uri_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <log_level> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <report_ack> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <report_cancels> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <detect_direction> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <log_flag> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <log_missed_flag> in module acc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: acc matches module acc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <failed_transaction_flag> in module acc [/usr/local/lib/opensips/module]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: usrloc matches module usrloc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_mode> in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: usrloc matches module usrloc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <timer_interval> in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: usrloc matches module usrloc
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <desc_time_order> in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db matches module auth_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <calculate_ha1> in module auth_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth_db matches module auth_db
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <password_column> in module auth_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth matches module auth
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <rpid_prefix> in module auth [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: auth matches module auth
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <rpid_suffix> in module auth [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: tm matches module tm
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <fr_timer> in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: tm matches module tm
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <fr_inv_timer> in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: tm matches module tm
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <wt_timer> in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: maxfwd matches module maxfwd
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <max_limit> in module maxfwd [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: xlog matches module xlog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <buf_size> in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: avpops matches module avpops
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <avp_url> in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: avpops matches module avpops
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <avp_table> in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: avpops matches module avpops
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_scheme> in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:avpops:avp_add_db_scheme: new scheme <iptrust> added
                uuid_col=<>
                username_col=<>
                domain_col=<>
                value_col=<>
                db_flags=2
                table=<iptrust>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <deniedps)$> for avp id <10>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <city> for avp id <11>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <USI> for avp id <12>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <RTK> for avp id <13>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <Deltatel> for avp id <14>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <Voipexchange> for avp id <15>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <ip_address> for avp id <20>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <trunc> for avp id <21>
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <iptr> for avp id <30>
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <dlg_flag> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <default_timeout> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <dlg_match_mode> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_mode> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <db_update_period> in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: dialog matches module dialog
Jan 20 14:38:59 [53020] DBG:core:set_mod_param_regex: found <profiles_with_value> in module dialog [/usr/local/lib/opensips/modules]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <mf_process_maxfwd_header>(1) in module maxfwd [/usr/local/lib/opensips/m]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <is_method>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <record_route>(0) in module rr [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <is_method>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <options_reply>(0) in module options [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <is_method>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <is_method>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <is_method>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <t_relay>(0) in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_reply_error>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <lookup>(1) in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <proxy_authorize>(2) in module auth_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <proxy_challenge>(2) in module auth [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <uac_replace_from>(2) in module uac [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_pushto>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <get_profile_size>(3) in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_db_load>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <get_profile_size>(3) in module dialog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <avp_check>(2) in module avpops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <search>(1) in module textops [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <check_to>(0) in module uri_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <save>(1) in module registrar [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_reply_error>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <check_from>(0) in module uri_db [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_send_reply>(2) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <t_relay>(0) in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <xlog>(2) in module xlog [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <sl_reply_error>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:socket2str: <udp:192.168.128.6:5060>
Jan 20 14:38:59 [53020] DBG:core:socket2str: <udp:192.168.193.62:5060>
Jan 20 14:38:59 [53020] DBG:core:socket2str: <udp:127.0.0.1:5060>
Jan 20 14:38:59 [53020] DBG:core:socket2str: <tcp:192.168.128.6:5060>
Jan 20 14:38:59 [53020] DBG:core:socket2str: <tcp:192.168.193.62:5060>
Jan 20 14:38:59 [53020] DBG:core:socket2str: <tcp:127.0.0.1:5060>
Listening on
             udp: 192.168.128.6 [192.168.128.6]:5060
             udp: 192.168.193.62 [192.168.193.62]:5060
             udp: 127.0.0.1 [127.0.0.1]:5060
             tcp: 192.168.128.6 [192.168.128.6]:5060
             tcp: 192.168.193.62 [192.168.193.62]:5060
             tcp: 127.0.0.1 [127.0.0.1]:5060
Aliases:
             tcp: localhost:5060
             tcp: sips.extrim.ru:5060
             tcp: sips.epn.ru:5060
             udp: localhost:5060
             udp: sips.extrim.ru:5060
             udp: sips.epn.ru:5060

Jan 20 14:38:59 [53020] WARNING:core:main: no fork mode  and more than one listen address found(will use only the first one)
Jan 20 14:38:59 [53020] DBG:core:fm_malloc_init: F_OPTIMIZE=16384, /ROUNDTO=2048
Jan 20 14:38:59 [53020] DBG:core:fm_malloc_init: F_HASH_SIZE=2067, fm_block size=16560
Jan 20 14:38:59 [53020] DBG:core:fm_malloc_init: params (0x28445000, 33554432), start=0x28445000
Jan 20 14:38:59 [53020] DBG:core:shm_mem_init_mallocs: success
Jan 20 14:38:59 [53020] INFO:core:init_tcp: using kqueue as the TCP io watch method (auto detected)
Jan 20 14:38:59 [53020] DBG:core:set_core_dump: core dump limits set to 31
Jan 20 14:38:59 [53020] NOTICE:core:main: version: opensips 1.4.4-notls (i386/freebsd)
Jan 20 14:38:59 [53020] INFO:core:main: using 32 Mb shared memory
Jan 20 14:38:59 [53020] INFO:core:main: using 1 Mb private memory per process
Jan 20 14:38:59 [53020] DBG:core:add_avp_galias: registering <serial_branch> for avp id <16725044>
Jan 20 14:38:59 [53020] DBG:core:init_stats_collector: statistics manager successfully initialized
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module db_mysql
Jan 20 14:38:59 [53020] DBG:db_mysql:mysql_mod_init: mysql: MySQL client version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module sl
Jan 20 14:38:59 [53020] INFO:sl:mod_init: Initializing StateLess engine
Jan 20 14:38:59 [53020] DBG:core:MD5StringArray: MD5 calculated: 0a020eec96699b0096d19557953be64e
Jan 20 14:38:59 [53020] DBG:core:init_mod: registering stats for sl
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module tm
Jan 20 14:38:59 [53020] INFO™️mod_init: TM - initializing...
Jan 20 14:38:59 [53020] DBG™️init_callid: Call-ID initialization: '7fad6e8a'
Jan 20 14:38:59 [53020] DBG™️lock_initialize: lock initialization started
Jan 20 14:38:59 [53020] DBG:core:MD5StringArray: MD5 calculated: 936e4f900e3e1ff3b9ece41834b610af
Jan 20 14:38:59 [53020] DBG:core:MD5StringArray: MD5 calculated: 6ed1767984500d79c9c0150155a02e43
Jan 20 14:38:59 [53020] DBG:core:init_mod: registering stats for tm
Jan 20 14:38:59 [53020] DBG:core:init_mod: register MI for tm
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module rr
Jan 20 14:38:59 [53020] DBG:rr:mod_init: rr - initializing
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module maxfwd
Jan 20 14:38:59 [53020] INFO:maxfwd:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module usrloc
Jan 20 14:38:59 [53020] DBG:usrloc:mod_init: initializing
Jan 20 14:38:59 [53020] INFO:usrloc:ul_init_locks: locks array size 512
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:init_mod: registering stats for usrloc
Jan 20 14:38:59 [53020] DBG:core:init_mod: register MI for usrloc
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module registrar
Jan 20 14:38:59 [53020] INFO:registrar:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_sl>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <ul_bind_usrloc>(1) in module usrloc [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:init_mod: registering stats for registrar
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module textops
Jan 20 14:38:59 [53020] INFO:textops:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module mi_fifo
Jan 20 14:38:59 [53020] DBG:mi_fifo:mi_mod_init: testing fifo existance ...
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module uri_db
Jan 20 14:38:59 [53020] DBG:uri_db:mod_init: uri_db - initializing
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a19d8 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a1ac0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1b08)[0]=[table_version]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a1b18
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 20 bytes for row values at 0x81a1b28
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [6]
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a1b28
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a1b18
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a1ac0
Jan 20 14:38:59 [53020] DBG:core:pool_remove: removing connection from the pool
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module xlog
Jan 20 14:38:59 [53020] INFO:xlog:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module acc
Jan 20 14:38:59 [53020] INFO:acc:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_tm>(0) in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module auth
Jan 20 14:38:59 [53020] INFO:auth:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_sl>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module auth_db
Jan 20 14:38:59 [53020] INFO:auth_db:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <bind_auth>(0) in module auth [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_sl>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module group
Jan 20 14:38:59 [53020] DBG:group:mod_init: group module - initializing
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a1a08 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a1a88
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1b08)[0]=[table_version]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 20 bytes for row values at 0x81a1b80
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [2]
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a1b80
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a1a88
Jan 20 14:38:59 [53020] DBG:core:pool_remove: removing connection from the pool
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module avpops
Jan 20 14:38:59 [53020] INFO:avpops:avpops_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module options
Jan 20 14:38:59 [53020] INFO:options:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_sl>(0) in module sl [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module uac
Jan 20 14:38:59 [53020] INFO:uac:mod_init: initializing...
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_tm>(0) in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_rr>(0) in module rr [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:init_mod: initializing module dialog
Jan 20 14:38:59 [53020] INFO:dialog:mod_init: Dialog module - initializing
Jan 20 14:38:59 [53020] DBG:dialog:add_profile_definitions: creating profile <calls>
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_tm>(0) in module tm [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_cmd_export_t: found <load_rr>(0) in module rr [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:find_mod_export: found <db_bind_api> in module db_mysql [/usr/local/lib/opensips/modules/]
Jan 20 14:38:59 [53020] DBG:core:db_bind_mod: using db bind api for db_mysql
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a1a08 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a1bf0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1af8)[0]=[table_version]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 20 bytes for row values at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [2]
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a1bf0
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a1bf0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 18 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 72 bytes for result names at 0x81a1c40
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 72 bytes for result types at 0x81a1c90
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1b08)[0]=[hash_entry]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1ae8)[1]=[hash_id]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1b70)[2]=[callid]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[3] at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1af8)[3]=[from_uri]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1aa0)[4]=[from_tag]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[5] at 0x81a1ab0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1ab0)[5]=[to_uri]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[6] at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1c18)[6]=[to_tag]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[7] at 0x81a1c28
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1c28)[7]=[start_time]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[8] at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d28)[8]=[state]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[9] at 0x81a1d38
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d38)[9]=[timeout]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[10] at 0x81a1d48
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d48)[10]=[caller_cseq]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[11] at 0x81a1d58
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d58)[11]=[callee_cseq]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[12] at 0x81a1d68
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d68)[12]=[caller_route_set]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[13] at 0x81a1d78
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d78)[13]=[callee_route_set]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[14] at 0x81a1d88
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d88)[14]=[caller_contact]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[15] at 0x81a1d98
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d98)[15]=[callee_contact]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[16] at 0x81a1da8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1da8)[16]=[caller_sock]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[17] at 0x81a1db8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1db8)[17]=[callee_sock]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_fetch_result: converting row 0 of 1 count 1
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 360 bytes for row values at 0x8186f90
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [2706]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [2050297634]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [ZmEyODU2NTY2NjA0MTJiZjcyYzQ5NDg5OGJjYzg3Nzg.]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [sip:3790990@192.168.128.6]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [01672905]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [sip:3790007@192.168.128.6]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [1c1512965863]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [1232444105]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [3]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [1232444050]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [2]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [2]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [sip:3790990@192.168.192.41:44010]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [sip:1111135@192.168.131.2]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [udp:192.168.128.6:5060]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [udp:192.168.128.6:5060]
Jan 20 14:38:59 [53020] DBG:dialog:load_dialog_info_from_db: loading information from database for 1 dialogs
Jan 20 14:38:59 [53020] DBG:dialog:build_new_dlg: new dialog on hash 2706
Jan 20 14:38:59 [53020] DBG:dialog:link_dlg: ref dlg 0x285e20c8 with 1 -> 1
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.168.128.6] == [192.168.128.6]
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.168.128.6] == [192.168.128.6]
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 20 14:38:59 [53020] DBG:dialog:insert_dlg_timer_unsafe: inserting 0x285e20f0 for 0
Jan 20 14:38:59 [53020] DBG:dialog:ref_dlg: ref dlg 0x285e20c8 with 1 -> 2
Jan 20 14:38:59 [53020] DBG:dialog:load_dialog_info_from_db: current dialog timeout is 0
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x8186f90
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a1dc8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 18 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1b08
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a1ae8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a1b70
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[3] at 0x81a1af8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[4] at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[5] at 0x81a1ab0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[6] at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[7] at 0x81a1c28
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[8] at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[9] at 0x81a1d38
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[10] at 0x81a1d48
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[11] at 0x81a1d58
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[12] at 0x81a1d68
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[13] at 0x81a1d78
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[14] at 0x81a1d88
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[15] at 0x81a1d98
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[16] at 0x81a1da8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[17] at 0x81a1db8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1c40
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1c90
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a1bf0
Jan 20 14:38:59 [53020] DBG:core:pool_remove: removing connection from the pool
Jan 20 14:38:59 [53020] DBG:core:init_mod: registering stats for dialog
Jan 20 14:38:59 [53020] DBG:core:init_mod: register MI for dialog
Jan 20 14:38:59 [53020] DBG:core:count_module_procs: modules require 1 extra processes
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing mf_process_maxfwd_header, line 132
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 133
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 134
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 139
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 140
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing is_method, line 146
Jan 20 14:38:59 [53020] DBG:core:parse_methods: methods 0xA0
Jan 20 14:38:59 [53020] DBG:textops:fixup_method: using id for methods [REGISTER,OPTIONS/160]
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 147
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing record_route, line 148
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing is_method, line 161
Jan 20 14:38:59 [53020] DBG:core:parse_methods: methods 0x20
Jan 20 14:38:59 [53020] DBG:textops:fixup_method: using id for method [OPTIONS/32]
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 162
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing options_reply, line 163
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing is_method, line 170
Jan 20 14:38:59 [53020] DBG:core:parse_methods: methods 0x80
Jan 20 14:38:59 [53020] DBG:textops:fixup_method: using id for method [REGISTER/128]
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 171
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing is_method, line 179
Jan 20 14:38:59 [53020] DBG:core:parse_methods: methods 0x1
Jan 20 14:38:59 [53020] DBG:textops:fixup_method: using id for method [INVITE/1]
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 180
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing is_method, line 192
Jan 20 14:38:59 [53020] DBG:core:parse_methods: methods 0x1E
Jan 20 14:38:59 [53020] DBG:textops:fixup_method: using id for methods [BYE,ACK,INFO,CANCEL/30]
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 193
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing t_relay, line 194
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 195
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_reply_error, line 196
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 204
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 205
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 212
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 219
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 223
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 223
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 226
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 231
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 236
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 236
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 237
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 242
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 243
Jan 20 14:38:59 [53020] DBG:avpops:parse_check_value: flag==8/1
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 244
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 249
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 258
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 262
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 262
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 263
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing lookup, line 268
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a1a08 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a21e8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1ab0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1ab0)[0]=[table_version]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 20 bytes for row values at 0x81a2220
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [1004]
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1ab0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a2220
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a21e8
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a21e8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a1d28)[0]=[username]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a1d28
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1aa0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a1c18
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a21e8
Jan 20 14:38:59 [53020] DBG:core:pool_remove: removing connection from the pool
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 271
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 276
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 279
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 284
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 285
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 291
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 291
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 292
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 301
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 301
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 302
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 316
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 316
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 317
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 421
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 421
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 422
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 431
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 431
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 432
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 441
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 441
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 442
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 451
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 451
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 452
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 460
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 466
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing proxy_authorize, line 468
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x8194ed8 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a2878
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a1dc8
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a28a0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a28b0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[0]=[table_version]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a28c0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 20 bytes for row values at 0x81a28d0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [6]
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a28b0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a1dc8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a28a0
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a28d0
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a28c0
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a2878
Jan 20 14:38:59 [53020] DBG:core:pool_remove: removing connection from the pool
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 469
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 470
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing proxy_challenge, line 471
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 474
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 482
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing uac_replace_from, line 486
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 487
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_pushto, line 496
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 514
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 515
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 524
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 528
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 530
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing get_profile_size, line 532
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_db_load, line 535
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 537
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing get_profile_size, line 539
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 541
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing avp_check, line 542
Jan 20 14:38:59 [53020] DBG:avpops:parse_check_value: flag==8/8
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 543
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 552
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing search, line 553
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 554
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 555
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 562
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 563
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing check_to, line 570
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 571
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 572
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing save, line 575
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_reply_error, line 576
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 580
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 582
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 588
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 592
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 593
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 599
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 600
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing check_from, line 609
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 610
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 611
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 619
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 620
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_send_reply, line 632
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 637
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 641
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 644
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing t_relay, line 647
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing xlog, line 648
Jan 20 14:38:59 [53020] DBG:core:fix_actions: fixing sl_reply_error, line 649
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: getsockopt SO_RCVBUF is initially 42080
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 84160
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=84160,verify=84160
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 168320
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=168320,verify=168320
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 170368
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=170368,verify=170368
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 172416
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=172416,verify=172416
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 174464
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=174464,verify=174464
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 176512
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=176512,verify=176512
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 178560
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=178560,verify=178560
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 180608
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=180608,verify=180608
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 182656
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=182656,verify=182656
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 184704
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=184704,verify=184704
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 186752
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=186752,verify=186752
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 188800
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=188800,verify=188800
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 190848
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=190848,verify=190848
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 192896
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=192896,verify=192896
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 194944
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=194944,verify=194944
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 196992
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=196992,verify=196992
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 199040
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=199040,verify=199040
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 201088
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=201088,verify=201088
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 203136
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=203136,verify=203136
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 205184
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=205184,verify=205184
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 207232
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=207232,verify=207232
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 209280
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=209280,verify=209280
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 211328
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=211328,verify=211328
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 213376
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=213376,verify=213376
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 215424
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=215424,verify=215424
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 217472
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=217472,verify=217472
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 219520
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=219520,verify=219520
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 221568
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=221568,verify=221568
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 223616
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=223616,verify=223616
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 225664
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=225664,verify=225664
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 227712
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=227712,verify=227712
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 229760
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=229760,verify=229760
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 231808
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setting SO_RCVBUF; set=231808,verify=231808
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: trying SO_RCVBUF: 233856
Jan 20 14:38:59 [53020] DBG:core:probe_max_receive_buffer: setsockopt: SOL_SOCKET failed for 233856, phase 1: No buffer space availe
Jan 20 14:38:59 [53020] INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 226 kb
Jan 20 14:38:59 [53020] WARNING:core:main_loop: using only the first listen address (no fork)
Jan 20 14:38:59 [53020] DBG:core:internal_fork: forking new process "timer"
Jan 20 14:38:59 [53020] DBG:core:start_module_procs: forking process "MI FIFO"/0 for module mi_fifo
Jan 20 14:38:59 [53020] DBG:core:internal_fork: forking new process "MI FIFO"
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=tm
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=tm
Jan 20 14:38:59 [53022] DBG:mi_fifo:fifo_process: new process with pid = 53022 created
Jan 20 14:38:59 [53021] DBG™️child_init_callid: callid: '7fad6e8a-53021@192.168.128.6'
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=usrloc
Jan 20 14:38:59 [53020] DBG™️child_init_callid: callid: '7fad6e8a-53020@192.168.128.6'
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=usrloc
Jan 20 14:38:59 [53022] DBG:mi_fifo:mi_init_fifo_server: FIFO created @ /tmp/opensips_fifo
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a28d0 not found in pool
Jan 20 14:38:59 [53022] DBG:mi_fifo:mi_init_fifo_server: fifo /tmp/opensips_fifo opened, mode=666
Jan 20 14:38:59 [53021] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a28d0 not found in pool
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53022] DBG:core:db_do_init: connection 0x8194f48 not found in pool
Jan 20 14:38:59 [53022] DBG:db_mysql:db_mysql_new_connection: opening connection: mysql://xxxx:xxxx@localhost/opensips
Jan 20 14:38:59 [53021] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53021] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53021] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=registrar
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=mi_fifo
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=uri_db
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7c30 found in pool
Jan 20 14:38:59 [53022] DBG:db_mysql:db_mysql_new_connection: connection type is Localhost via UNIX socket
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=xlog
Jan 20 14:38:59 [53022] DBG:db_mysql:db_mysql_new_connection: protocol version is 10
Jan 20 14:38:59 [53021] DBG:xlog:child_init: init_child [-1]  pid [53021]
Jan 20 14:38:59 [53022] DBG:db_mysql:db_mysql_new_connection: server version is 5.1.30
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=acc
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7cc8 found in pool
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=auth_db
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7d70 found in pool
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=group
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7e18 found in pool
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=avpops
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7ec0 found in pool
Jan 20 14:38:59 [53021] DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=dialog
Jan 20 14:38:59 [53021] DBG:core:db_do_init: connection 0x81a7f68 found in pool
Jan 20 14:38:59 [53021] DBG:core:run_timer_process: tv = 0, 100000 , m=10
Jan 20 14:38:59 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a5c10
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: 14 columns returned from the query
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 56 bytes for result names at 0x81a5c38
Jan 20 14:38:59 [53020] DBG:core:db_allocate_columns: allocate 56 bytes for result types at 0x81a5c78
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a28b0
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[0]=[username]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5cb8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[1]=[contact]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cc8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[2]=[expires]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_DATETIME result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[3] at 0x81a5cd8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[3]=[q]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_DOUBLE result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x81a5ce8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5ce8)[4]=[callid]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[5] at 0x81a5cf8
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cf8)[5]=[cseq]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[6] at 0x81a5d08
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d08)[6]=[flags]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[7] at 0x81a5d18
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d18)[7]=[cflags]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[8] at 0x81a5d28
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d28)[8]=[user_agent]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[9] at 0x81a5d38
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d38)[9]=[received]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[10] at 0x81a5d48
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d48)[10]=[path]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[11] at 0x81a5d58
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d58)[11]=[socket]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[12] at 0x81a5d68
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d68)[12]=[methods]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[13] at 0x81a5d78
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d78)[13]=[last_modified]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_DATETIME result type
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_fetch_result: converting row 0 of 1 count 1
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 280 bytes for row values at 0x81a5d98
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [3790990]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [sip:3790990@192.168.192.41:44010;rinstance=1e6298b8b8e461]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting DATETIME [2009-01-20 15:29:00]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting DOUBLE [-1.00]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [OWIwZGVlMjM3Njk3MjNjODA4YTdkYjlhZWMwYjIyM2U.]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [2]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [0]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [0]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [X-Lite release 1011s stamp 41150]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [udp:192.168.128.6:5060]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [5951]
Jan 20 14:38:59 [53020] DBG:db_mysql:db_mysql_str2val: converting DATETIME [2009-01-20 14:29:00]
Jan 20 14:38:59 [53020] DBG:usrloc:preload_udomain: loading records - cycle [1]
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.168.128.6] == [192.168.128.6]
Jan 20 14:38:59 [53020] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_row: freeing row values at 0x81a5d98
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing rows at 0x81a5d88
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing 14 columns
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a28b0
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5cb8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cc8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[3] at 0x81a5cd8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[4] at 0x81a5ce8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[5] at 0x81a5cf8
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[6] at 0x81a5d08
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[7] at 0x81a5d18
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[8] at 0x81a5d28
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[9] at 0x81a5d38
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[10] at 0x81a5d48
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[11] at 0x81a5d58
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[12] at 0x81a5d68
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing RES_NAMES[13] at 0x81a5d78
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result names at 0x81a5c38
Jan 20 14:38:59 [53020] DBG:core:db_free_columns: freeing result types at 0x81a5c78
Jan 20 14:38:59 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:38:59 [53020] DBG:core:db_free_result: freeing result set at 0x81a5c10
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=registrar
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=mi_fifo
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=uri_db
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a5c78 found in pool
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=xlog
Jan 20 14:38:59 [53020] DBG:xlog:child_init: init_child [1]  pid [53020]
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=acc
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a5dc8 found in pool
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=auth_db
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a5e60 found in pool
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=group
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a7f08 found in pool
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=avpops
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a7fa0 found in pool
Jan 20 14:38:59 [53020] DBG:core:init_mod_child: type=CHILD, rank=1, module=dialog
Jan 20 14:38:59 [53020] DBG:core:db_do_init: connection 0x81a8038 found in pool
Jan 20 14:39:00 [53021] DBG:dialog:get_expired_dlgs: start with tl=0x285e20f0 tl->prev=0x285d0078 tl->next=0x285d0078 (0) at 1 and 0
Jan 20 14:39:00 [53021] DBG:dialog:get_expired_dlgs: getting tl=0x285e20f0 tl->prev=0x285d0078 tl->next=0x285d0078 with 0
Jan 20 14:39:00 [53021] DBG:dialog:get_expired_dlgs: end with tl=0x285d0078 tl->prev=0x285e20f0 tl->next=0x285e20f0 and d_timer->fi0
Jan 20 14:39:00 [53021] DBG:dialog:dlg_timer_routine: tl=0x285e20f0 next=0x0
Jan 20 14:39:00 [53021] DBG:dialog:next_state_dlg: dialog 0x285e20c8 changed from state 3 to state 5, due event 7
Jan 20 14:39:00 [53021] DBG:dialog:dlg_ontimeout: timeout for dlg with CallID 'ZmEyODU2NTY2NjA0MTJiZjcyYzQ5NDg5OGJjYzg3Nzg.' and ta'
Jan 20 14:39:00 [53021] DBG:dialog:remove_dialog_from_db: trying to remove a dialog, update_flag is 4
Jan 20 14:39:00 [53021] DBG:dialog:remove_dialog_from_db: callid was ZmEyODU2NTY2NjA0MTJiZjcyYzQ5NDg5OGJjYzg3Nzg.
Jan 20 14:39:00 [53021] DBG:dialog:unref_dlg: unref dlg 0x285e20c8 with 2 -> 0
Jan 20 14:39:00 [53021] DBG:dialog:unref_dlg: ref <=0 for dialog 0x285e20c8
Jan 20 14:39:00 [53021] DBG:dialog:destroy_dlg: destroing dialog 0x285e20c8
Jan 20 14:39:00 [53021] DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x285e20c8 [2706:2050297634] with clid 'ZmEyODU2NT'
Jan 20 14:39:01 [53020] DBG:core:udp_rcv_loop: probing packet received from 192.168.192.41 60075
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Request:
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  method:  <INVITE>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  uri:     <sip:3790007@192.168.128.6>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-da06624f3a6f864a-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:receive_msg: preparing to run routing scripts...
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=100
Jan 20 14:39:17 [53020] DBG:maxfwd:is_maxfwd_present: value = 70
Jan 20 14:39:17 [53020] DBG:maxfwd:w_process_maxfwd_header: value 70 decreased to 32
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=10
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=10
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [38]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>
]
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=c8390f1b
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790990"}, ruri={sip:3790990@192.168.128.6}
SCRIPT: Record route enable for URI: sip:3790990@192.168.128.6
SCRIPT: INVITE method from URI:sip:3790990@192.168.128.6 processed
SCRIPT: route 7 [INVITE]
Jan 20 14:39:17 [53020] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.168.128.6] == [192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
SCRIPT: route 1 [checking from_ip access]
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8b00
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
SCRIPT: route 3 [proxy autorization]
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=10000
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: content_length=458
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: found end of header
Jan 20 14:39:17 [53020] DBG:auth:pre_auth: credentials with given realm not found
SCRIPT: Authorization required for method INVITE from URI:sip:3790990@192.168.128.6 to sip:3790007@192.168.128.6
SCRIPT: Sending challenge request...
Jan 20 14:39:17 [53020] DBG:auth:reserve_nonce_index: second= 18, sec_monit= -1,  index= 0
Jan 20 14:39:17 [53020] DBG:auth:build_auth_hf: nonce index= 0
Jan 20 14:39:17 [53020] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="sips.epn.ru", nonce="49759be3000000008a7db573062"
'
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 20 14:39:17 [53020] DBG:core:check_via_address: params 192.168.192.41, 192.168.192.41, 0
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Request:
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  method:  <ACK>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  uri:     <sip:3790007@192.168.128.6>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-da06624f3a6f864a-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:receive_msg: preparing to run routing scripts...
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=0a020eec96699b0096d19557953be64e.dac8
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [80]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:17 [53020] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Request:
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  method:  <INVITE>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  uri:     <sip:3790007@192.168.128.6>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-4116be2a7553e170-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:receive_msg: preparing to run routing scripts...
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=100
Jan 20 14:39:17 [53020] DBG:maxfwd:is_maxfwd_present: value = 70
Jan 20 14:39:17 [53020] DBG:maxfwd:w_process_maxfwd_header: value 70 decreased to 32
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=10
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=10
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [38]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>
]
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=c8390f1b
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790990"}, ruri={sip:3790990@192.168.128.6}
SCRIPT: Record route enable for URI: sip:3790990@192.168.128.6
SCRIPT: INVITE method from URI:sip:3790990@192.168.128.6 processed
SCRIPT: route 7 [INVITE]
Jan 20 14:39:17 [53020] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.168.128.6] == [192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
SCRIPT: route 1 [checking from_ip access]
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result names at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 1 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cb8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a84c0
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
SCRIPT: route 3 [proxy autorization]
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=10000
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Jan 20 14:39:17 [53020] DBG:auth:check_nonce: comparing [49759be3000000008a7db57306261cb6613f4b8c3d9e7635] and [49759be3000000008a7]
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 8 bytes for result types at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[0]=[password]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d88)[1]=[rpid]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 40 bytes for row values at 0x81a8c78
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [654321]
Jan 20 14:39:17 [53020] DBG:auth_db:get_ha1: HA1 string calculated: 2e7ec9e410dd83e5d8dd1429e86a60ec
Jan 20 14:39:17 [53020] DBG:auth:check_response: our result = '2b000e39d6ebb9715bc4f1282cb2282f'
Jan 20 14:39:17 [53020] DBG:auth:check_response: authorization is OK
Jan 20 14:39:17 [53020] DBG:auth:post_auth: nonce index= 0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 2 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a5cb8
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_row: freeing row values at 0x81a8c78
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing rows at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8410
SCRIPT: sip:3790990@192.168.128.6 successfully proxy-authorized.
Jan 20 14:39:17 [53020] DBG:uri_db:check_username: Digest username and URI username match
Jan 20 14:39:17 [53020] DBG:core:comp_scriptvar: str 20 : sip:3790990@192.168.128.6
SCRIPT: route 2 [checkink by prefix and define destination]
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d88)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:registrar:lookup: '3790007' Not found in usrloc
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d88)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
Jan 20 14:39:17 [53020] DBG:avpops:ops_check_avp: no src avp found
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cc8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d88)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_row: allocate 60 bytes for row values at 0x81a8d20
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [1]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_str2val: converting STRING [11]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_str2val: converting INT [3]
Jan 20 14:39:17 [53020] DBG:avpops:dbrow2avp: db_flags=0, flags=10
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cc8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 1 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_row: freeing row values at 0x81a8d20
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing rows at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 1
Jan 20 14:39:17 [53020] DBG:avpops:ops_check_avp: check <1> against <1> as int /1
SCRIPT: route 4 [rewrite host]
SCRIPT: route 5 [check for free trunc for user]
Jan 20 14:39:17 [53020] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_allocate_columns: allocate 12 bytes for result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5cd8)[0]=[value]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a28b0)[1]=[attribute]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81a5d88)[2]=[type]
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jan 20 14:39:17 [53020] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jan 20 14:39:17 [53020] DBG:avpops:db_close_query: close avp query
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing 3 columns
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x81a5cd8
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81a28b0
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x81a5d88
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result names at 0x81a8b40
Jan 20 14:39:17 [53020] DBG:core:db_free_columns: freeing result types at 0x81a8b28
Jan 20 14:39:17 [53020] DBG:core:db_free_rows: freeing 0 rows
Jan 20 14:39:17 [53020] DBG:core:db_free_result: freeing result set at 0x81a8410
Jan 20 14:39:17 [53020] DBG:avpops:ops_dbload_avps: loaded avps = 0
SCRIPT: Outcomming call. No trunc info for sip:3790990@192.168.128.6 in usr_preferences. Call allow
SCRIPT: from sip:3790990@192.168.128.6 to sip:3790007@192.168.131.2  Var=0, AVP=<null>
Jan 20 14:39:17 [53020] DBG:avpops:ops_check_avp: no src avp found
SCRIPT: Dialog flag enable
SCRIPT: Outcomming call. Add 3790990 to dialog profile
Jan 20 14:39:17 [53020] DBG™️t_newtran: transaction on entrance=0xffffffff
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: content_length=458
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: found end of header
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=78
Jan 20 14:39:17 [53020] DBG™️t_lookup_request: start searching: hash=64028, isACK=0
Jan 20 14:39:17 [53020] DBG™️matching_3261: RFC3261 transaction matching failed
Jan 20 14:39:17 [53020] DBG™️t_lookup_request: no transaction found
Jan 20 14:39:17 [53020] DBG™️run_reqin_callbacks: trans=0x285e4ff0, callback type 1, id 1 entered
Jan 20 14:39:17 [53020] DBG:dialog:build_new_dlg: new dialog on hash 3958
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=20
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=400
Jan 20 14:39:17 [53020] DBG:dialog:populate_leg_info: route_set , contact sip:3790990@192.168.192.41:44010, cseq 2 and bind_addr ud0
Jan 20 14:39:17 [53020] DBG:dialog:link_dlg: ref dlg 0x285e20c8 with 3 -> 3
Jan 20 14:39:17 [53020] DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeoutJan 20 14:39:17 [53020] DBG™️run_reqin_d
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 20 14:39:17 [53020] DBG:core:check_via_address: params 192.168.192.41, 192.168.192.41, 0
Jan 20 14:39:17 [53020] DBG:core:_shm_resize: resize(0) called
Jan 20 14:39:17 [53020] DBG™️_reply_light: reply sent out. buf=0x81a8de8: SIP/2.0 1..., shmem=0x285e6e30: SIP/2.0 1
Jan 20 14:39:17 [53020] DBG™️_reply_light: finished
Jan 20 14:39:17 [53020] DBG:core:mk_proxy: doing DNS lookup...
Jan 20 14:39:17 [53020] DBG™️set_timer: relative timeout is 500000
Jan 20 14:39:17 [53020] DBG™️insert_timer_unsafe: [4]: 0x285e513c (18700000)
Jan 20 14:39:17 [53020] DBG™️set_timer: relative timeout is 15
Jan 20 14:39:17 [53020] DBG™️insert_timer_unsafe: [0]: 0x285e5158 (33)
Jan 20 14:39:17 [53020] DBG™️t_relay_to: new transaction fwd'ed
Jan 20 14:39:17 [53020] DBG:dialog:unref_dlg: unref dlg 0x285e20c8 with 1 -> 2
Jan 20 14:39:17 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Reply  (status):
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  status:  <100>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  reason:  <Trying>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc1af.ca3c8862.0>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:forward_reply: found module tm, passing reply to it
Jan 20 14:39:17 [53020] DBG™️t_check: start=0xffffffff
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 234, <received> = <192.168.192.41>; state=6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-4116be2a7553e170-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <44010>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_headers: parse_headers: this is the second via
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: hash 64028 label 646497196 branch 0
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: REF_UNSAFE: after is 1
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: reply matched (T=0x285e4ff0)!
Jan 20 14:39:17 [53020] DBG™️t_check: end=0x285e4ff0
Jan 20 14:39:17 [53020] DBG™️reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Jan 20 14:39:17 [53020] DBG™️t_should_relay_response: T_code=100, new_code=100
Jan 20 14:39:17 [53020] DBG™️relay_reply: branch=0, save=0, relay=-1
Jan 20 14:39:17 [53020] DBG™️set_timer: relative timeout is 100
Jan 20 14:39:17 [53020] DBG™️insert_timer_unsafe: [1]: 0x285e5158 (118)
Jan 20 14:39:17 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Reply  (status):
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  status:  <183>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  reason:  <Session Progress>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc1af.ca3c8862.0>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:forward_reply: found module tm, passing reply to it
Jan 20 14:39:17 [53020] DBG™️t_check: start=0xffffffff
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 234, <received> = <192.168.192.41>; state=6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-4116be2a7553e170-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <44010>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_headers: parse_headers: this is the second via
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: hash 64028 label 646497196 branch 0
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: REF_UNSAFE: after is 1
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: reply matched (T=0x285e4ff0)!
Jan 20 14:39:17 [53020] DBG™️t_check: end=0x285e4ff0
Jan 20 14:39:17 [53020] DBG™️reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Jan 20 14:39:17 [53020] DBG™️t_should_relay_response: T_code=100, new_code=183
Jan 20 14:39:17 [53020] DBG™️relay_reply: branch=0, save=0, relay=0
Jan 20 14:39:17 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 16, id 0 entered
Jan 20 14:39:17 [53020] DBG:core:build_res_buf_from_sip_res:  old size: 954, new size: 892
Jan 20 14:39:17 [53020] DBG:core:build_res_buf_from_sip_res: copied size: orig:92, new: 30, rest: 862 msg=
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.192.41:44010;received=192.168.192.41;branch=z9hG4bK-d87543-4116be2a7553e170-1--d87543-;rport=44010
From: "3790990"<sip:3790990@192.168.128.6>;tag=c8390f1b
To: "3790007"<sip:3790007@192.168.128.6>;tag=1c1404466542
Call-ID: NDkyODY3MjYwNTQxY2I1Yzg3OWZiODVkOTVkNGU0ODM.
CSeq: 2 INVITE
Contact: <sip:1111122@192.168.131.2>
Record-Route: <sip:192.168.128.6;lr=on;ftag=c8390f1b;did=67f.9d807ae>
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 2000/v.4.60A.028.003
Content-Type: application/sdp
Content-Length: 203

v=0
o=AudiocodesGW 1404494865 1404494490 IN IP4 192.168.131.2
s=Phone-Call
c=IN IP4 192.168.131.2
t=0 0
m=audio 6110 RTP/AVP 8
a=rtpmap:8 pcma/8000
a=ptime:20
a=sendrecv
m=video 0 RTP/AVP 34

Jan 20 14:39:17 [53020] DBG™️relay_reply: sent buf=0x81a8fc8: SIP/2.0 1..., shmem=0x285e75f8: SIP/2.0 1
Jan 20 14:39:17 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 128, id 0 entered
Jan 20 14:39:17 [53020] DBG:dialog:next_state_dlg: dialog 0x285e20c8 changed from state 1 to state 2, due event 2
Jan 20 14:39:17 [53020] DBG™️set_timer: relative timeout is 100
Jan 20 14:39:17 [53020] DBG™️insert_timer_unsafe: [1]: 0x285e5158 (118)
Jan 20 14:39:17 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:17 [53020] DBG:core:parse_msg: SIP Reply  (status):
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  status:  <180>
Jan 20 14:39:17 [53020] DBG:core:parse_msg:  reason:  <Ringing>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc1af.ca3c8862.0>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:17 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:17 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:17 [53020] DBG:core:forward_reply: found module tm, passing reply to it
Jan 20 14:39:17 [53020] DBG™️t_check: start=0xffffffff
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 234, <received> = <192.168.192.41>; state=6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-4116be2a7553e170-1--d87543->; st6
Jan 20 14:39:17 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <44010>; state=16
Jan 20 14:39:17 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:17 [53020] DBG:core:parse_headers: via found, flags=22
Jan 20 14:39:17 [53020] DBG:core:parse_headers: parse_headers: this is the second via
Jan 20 14:39:17 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:17 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:17 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:17 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Jan 20 14:39:17 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: hash 64028 label 646497196 branch 0
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: REF_UNSAFE: after is 1
Jan 20 14:39:17 [53020] DBG™️t_reply_matching: reply matched (T=0x285e4ff0)!
Jan 20 14:39:17 [53020] DBG™️t_check: end=0x285e4ff0
Jan 20 14:39:17 [53020] DBG™️reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1)
Jan 20 14:39:17 [53020] DBG™️t_should_relay_response: T_code=183, new_code=180
Jan 20 14:39:17 [53020] DBG™️relay_reply: branch=0, save=0, relay=0
Jan 20 14:39:17 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 16, id 0 entered
Jan 20 14:39:17 [53020] DBG:core:build_res_buf_from_sip_res:  old size: 945, new size: 883
Jan 20 14:39:17 [53020] DBG:core:build_res_buf_from_sip_res: copied size: orig:83, new: 21, rest: 862 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.192.41:44010;received=192.168.192.41;branch=z9hG4bK-d87543-4116be2a7553e170-1--d87543-;rport=44010
From: "3790990"<sip:3790990@192.168.128.6>;tag=c8390f1b
To: "3790007"<sip:3790007@192.168.128.6>;tag=1c1404466542
Call-ID: NDkyODY3MjYwNTQxY2I1Yzg3OWZiODVkOTVkNGU0ODM.
CSeq: 2 INVITE
Contact: <sip:1111122@192.168.131.2>
Record-Route: <sip:192.168.128.6;lr=on;ftag=c8390f1b;did=67f.9d807ae>
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 2000/v.4.60A.028.003
Content-Type: application/sdp
Content-Length: 203

v=0
o=AudiocodesGW 1404494865 1404494490 IN IP4 192.168.131.2
s=Phone-Call
c=IN IP4 192.168.131.2
t=0 0
m=audio 6110 RTP/AVP 8
a=rtpmap:8 pcma/8000
a=ptime:20
a=sendrecv
m=video 0 RTP/AVP 34

Jan 20 14:39:17 [53020] DBG™️relay_reply: sent buf=0x81a8fc8: SIP/2.0 1..., shmem=0x285e75f8: SIP/2.0 1
Jan 20 14:39:17 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 128, id 0 entered
Jan 20 14:39:17 [53020] DBG:dialog:next_state_dlg: dialog 0x285e20c8 changed from state 2 to state 2, due event 2
Jan 20 14:39:17 [53020] DBG™️set_timer: relative timeout is 100
Jan 20 14:39:17 [53020] DBG™️insert_timer_unsafe: [1]: 0x285e5158 (118)
Jan 20 14:39:17 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:17 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:17 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:18 [53021] DBG™️utimer_routine: timer routine:4,tl=0x285e513c next=0x0, timeout=18700000
Jan 20 14:39:20 [53020] DBG:core:parse_msg: SIP Reply  (status):
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  status:  <200>
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  reason:  <OK>
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc1af.ca3c8862.0>; state=16
Jan 20 14:39:20 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:20 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:20 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:20 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:20 [53020] DBG:core:forward_reply: found module tm, passing reply to it
Jan 20 14:39:20 [53020] DBG™️t_check: start=0xffffffff
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=22
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 234, <received> = <192.168.192.41>; state=6
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-4116be2a7553e170-1--d87543->; st6
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <44010>; state=16
Jan 20 14:39:20 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:20 [53020] DBG:core:parse_headers: via found, flags=22
Jan 20 14:39:20 [53020] DBG:core:parse_headers: parse_headers: this is the second via
Jan 20 14:39:20 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:20 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:20 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:20 [53020] DBG™️t_reply_matching: hash 64028 label 646497196 branch 0
Jan 20 14:39:20 [53020] DBG™️t_reply_matching: REF_UNSAFE: after is 1
Jan 20 14:39:20 [53020] DBG™️t_reply_matching: reply matched (T=0x285e4ff0)!
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=8
Jan 20 14:39:20 [53020] DBG™️t_check: end=0x285e4ff0
Jan 20 14:39:20 [53020] DBG™️reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jan 20 14:39:20 [53020] DBG™️t_should_relay_response: T_code=180, new_code=200
Jan 20 14:39:20 [53020] DBG™️relay_reply: branch=0, save=0, relay=0
Jan 20 14:39:20 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 16, id 0 entered
Jan 20 14:39:20 [53020] DBG:core:build_res_buf_from_sip_res:  old size: 940, new size: 878
Jan 20 14:39:20 [53020] DBG:core:build_res_buf_from_sip_res: copied size: orig:78, new: 16, rest: 862 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.192.41:44010;received=192.168.192.41;branch=z9hG4bK-d87543-4116be2a7553e170-1--d87543-;rport=44010
From: "3790990"<sip:3790990@192.168.128.6>;tag=c8390f1b
To: "3790007"<sip:3790007@192.168.128.6>;tag=1c1404466542
Call-ID: NDkyODY3MjYwNTQxY2I1Yzg3OWZiODVkOTVkNGU0ODM.
CSeq: 2 INVITE
Contact: <sip:1111122@192.168.131.2>
Record-Route: <sip:192.168.128.6;lr=on;ftag=c8390f1b;did=67f.9d807ae>
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 2000/v.4.60A.028.003
Content-Type: application/sdp
Content-Length: 203

v=0
o=AudiocodesGW 1404494865 1404494490 IN IP4 192.168.131.2
s=Phone-Call
c=IN IP4 192.168.131.2
t=0 0
m=audio 6110 RTP/AVP 8
a=rtpmap:8 pcma/8000
a=ptime:20
a=sendrecv
m=video 0 RTP/AVP 34

Jan 20 14:39:20 [53020] DBG™️update_totag_set: new totag
Jan 20 14:39:20 [53020] DBG™️insert_timer_unsafe: [2]: 0x285e5038 (28)
Jan 20 14:39:20 [53020] DBG™️relay_reply: sent buf=0x81a8fc8: SIP/2.0 2..., shmem=0x285e75f8: SIP/2.0 2
Jan 20 14:39:20 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 128, id 0 entered
Jan 20 14:39:20 [53020] DBG:dialog:next_state_dlg: dialog 0x285e20c8 changed from state 2 to state 3, due event 3
Jan 20 14:39:20 [53020] DBG:dialog:dlg_onreply: dialog 0x285e20c8 confirmed
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=80
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=400
Jan 20 14:39:20 [53020] DBG:core:print_rr_body: current rr is <sip:192.168.128.6;lr=on;ftag=c8390f1b;did=67f.9d807ae>
Jan 20 14:39:20 [53020] DBG:core:print_rr_body: skipping 1 route records
Jan 20 14:39:20 [53020] DBG:core:print_rr_body: out rr []
Jan 20 14:39:20 [53020] DBG:core:print_rr_body: we have 1 records
Jan 20 14:39:20 [53020] DBG:dialog:populate_leg_info: route_set , contact sip:1111122@192.168.131.2, cseq 2 and bind_addr udp:192.10
Jan 20 14:39:20 [53020] DBG:dialog:update_dialog_dbinfo: sock_info is udp:192.168.128.6:5060
Jan 20 14:39:20 [53020] DBG:dialog:insert_dlg_timer_unsafe: inserting 0x285e20f0 for 3620
Jan 20 14:39:20 [53020] DBG:dialog:ref_dlg: ref dlg 0x285e20c8 with 1 -> 3
Jan 20 14:39:20 [53020] DBG™️cleanup_uac_timers: RETR/FR timers reset
Jan 20 14:39:20 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:20 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:20 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:20 [53020] DBG:core:parse_msg: SIP Request:
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  method:  <ACK>
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  uri:     <sip:1111122@192.168.131.2>
Jan 20 14:39:20 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-80269b5a48531f14-1--d87543->; st6
Jan 20 14:39:20 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan 20 14:39:20 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:20 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:20 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:20 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:20 [53020] DBG:core:receive_msg: preparing to run routing scripts...
Jan 20 14:39:20 [53020] DBG:sl:sl_filter_ACK: to late to be a local ACK!
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=100
Jan 20 14:39:20 [53020] DBG:maxfwd:is_maxfwd_present: value = 70
Jan 20 14:39:20 [53020] DBG:maxfwd:w_process_maxfwd_header: value 70 decreased to 32
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=10
Jan 20 14:39:20 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:20 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:20 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:20 [53020] DBG:core:parse_to_param: tag=c8390f1b
Jan 20 14:39:20 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:20 [53020] DBG:core:parse_to: display={"3790990"}, ruri={sip:3790990@192.168.128.6}
SCRIPT: Record route enable for URI: sip:3790990@192.168.128.6
SCRIPT: ACK method from URI:sip:3790990@192.168.128.6 processed
Jan 20 14:39:20 [53020] DBG™️t_newtran: transaction on entrance=0xffffffff
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <2> <ACK>
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: content_length=0
Jan 20 14:39:20 [53020] DBG:core:get_hdr_field: found end of header
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=78
Jan 20 14:39:20 [53020] DBG™️t_lookup_request: start searching: hash=64028, isACK=1
Jan 20 14:39:20 [53020] DBG:core:parse_headers: flags=38
Jan 20 14:39:20 [53020] DBG™️t_lookup_request: REF_UNSAFE: after is 1
Jan 20 14:39:20 [53020] DBG™️t_lookup_request: e2e proxy ACK found
Jan 20 14:39:20 [53020] DBG™️t_newtran: building branch for end2end ACK
Jan 20 14:39:20 [53020] DBG™️t_relay_to: forwarding ACK
Jan 20 14:39:20 [53020] DBG:core:mk_proxy: doing DNS lookup...
Jan 20 14:39:20 [53020] DBG:core:forward_request: sending:
ACK sip:1111122@192.168.131.2 SIP/2.0
Record-Route: <sip:192.168.128.6;lr=on;ftag=c8390f1b>
Via: SIP/2.0/UDP 192.168.128.6;branch=z9hG4bKc1af.ca3c8862.2
Via: SIP/2.0/UDP 192.168.192.41:44010;received=192.168.192.41;branch=z9hG4bK-d87543-80269b5a48531f14-1--d87543-;rport=44010
Max-Forwards: 32
Route: <sip:192.168.128.6;lr;ftag=c8390f1b;did=67f.9d807ae>
Contact: <sip:3790990@192.168.192.41:44010>
To: "3790007"<sip:3790007@192.168.128.6>;tag=1c1404466542
From: "3790990"<sip:3790990@192.168.128.6>;tag=c8390f1b
Call-ID: NDkyODY3MjYwNTQxY2I1Yzg3OWZiODVkOTVkNGU0ODM.
CSeq: 2 ACK
Proxy-Authorization: Digest username="3790990",realm="sips.epn.ru",nonce="49759be3000000008a7db57306261cb6613f4b8c3d9e7635",uri="si5
User-Agent: X-Lite release 1011s stamp 41150
Content-Length: 0

.
Jan 20 14:39:20 [53020] DBG:core:forward_request: orig. len=724, new_len=871, proto=1
Jan 20 14:39:20 [53020] DBG™️t_unref_cell: UNREF_UNSAFE: after is 0
Jan 20 14:39:20 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:20 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:21 [53020] DBG:core:parse_msg: SIP Request:
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  method:  <BYE>
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  uri:     <sip:1111122@192.168.131.2>
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-0261dc62e83ee57f-1--d87543->; st6
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jan 20 14:39:21 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:21 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:21 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:21 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:21 [53020] DBG:core:receive_msg: preparing to run routing scripts...
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=100
Jan 20 14:39:21 [53020] DBG:maxfwd:is_maxfwd_present: value = 70
Jan 20 14:39:21 [53020] DBG:maxfwd:w_process_maxfwd_header: value 70 decreased to 32
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=10
Jan 20 14:39:21 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:21 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:21 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:21 [53020] DBG:core:parse_to_param: tag=c8390f1b
Jan 20 14:39:21 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:21 [53020] DBG:core:parse_to: display={"3790990"}, ruri={sip:3790990@192.168.128.6}
SCRIPT: Record route enable for URI: sip:3790990@192.168.128.6
SCRIPT: BYE method from URI:sip:3790990@192.168.128.6 processed
Jan 20 14:39:21 [53020] DBG™️t_newtran: transaction on entrance=0xffffffff
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: content_length=0
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: found end of header
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=78
Jan 20 14:39:21 [53020] DBG™️t_lookup_request: start searching: hash=64029, isACK=0
Jan 20 14:39:21 [53020] DBG™️matching_3261: RFC3261 transaction matching failed
Jan 20 14:39:21 [53020] DBG™️t_lookup_request: no transaction found
Jan 20 14:39:21 [53020] DBG™️run_reqin_callbacks: trans=0x285e7a20, callback type 1, id 1 entered
Jan 20 14:39:21 [53020] DBG™️run_reqin_callbacks: trans=0x285e7a20, callback type 1, id 0 entered
Jan 20 14:39:21 [53020] DBG:core:mk_proxy: doing DNS lookup...
Jan 20 14:39:21 [53020] DBG™️set_timer: relative timeout is 500000
Jan 20 14:39:21 [53020] DBG™️insert_timer_unsafe: [4]: 0x285e7b6c (22800000)
Jan 20 14:39:21 [53020] DBG™️set_timer: relative timeout is 15
Jan 20 14:39:21 [53020] DBG™️insert_timer_unsafe: [0]: 0x285e7b88 (37)
Jan 20 14:39:21 [53020] DBG™️t_relay_to: new transaction fwd'ed
Jan 20 14:39:21 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:21 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:21 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:21 [53020] DBG:core:parse_msg: SIP Reply  (status):
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  status:  <200>
Jan 20 14:39:21 [53020] DBG:core:parse_msg:  reason:  <OK>
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=2
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKd1af.7f466ec5.0>; state=16
Jan 20 14:39:21 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:21 [53020] DBG:core:parse_headers: via found, flags=2
Jan 20 14:39:21 [53020] DBG:core:parse_headers: this is the first via
Jan 20 14:39:21 [53020] DBG:core:receive_msg: After parse_msg...
Jan 20 14:39:21 [53020] DBG:core:forward_reply: found module tm, passing reply to it
Jan 20 14:39:21 [53020] DBG™️t_check: start=0xffffffff
Jan 20 14:39:21 [53020] DBG:core:parse_headers: flags=22
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 234, <received> = <192.168.192.41>; state=6
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-0261dc62e83ee57f-1--d87543->; st6
Jan 20 14:39:21 [53020] DBG:core:parse_via_param: found param type 235, <rport> = <44010>; state=16
Jan 20 14:39:21 [53020] DBG:core:parse_via: end of header reached, state=5
Jan 20 14:39:21 [53020] DBG:core:parse_headers: via found, flags=22
Jan 20 14:39:21 [53020] DBG:core:parse_headers: parse_headers: this is the second via
Jan 20 14:39:21 [53020] DBG:core:parse_to_param: tag=1c1404466542
Jan 20 14:39:21 [53020] DBG:core:parse_to: end of header reached, state=29
Jan 20 14:39:21 [53020] DBG:core:parse_to: display={"3790007"}, ruri={sip:3790007@192.168.128.6}
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: <To> [55]; uri=[sip:3790007@192.168.128.6]
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: to body ["3790007"<sip:3790007@192.168.128.6>]
Jan 20 14:39:21 [53020] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Jan 20 14:39:21 [53020] DBG™️t_reply_matching: hash 64029 label 1558602999 branch 0
Jan 20 14:39:21 [53020] DBG™️t_reply_matching: REF_UNSAFE: after is 1
Jan 20 14:39:21 [53020] DBG™️t_reply_matching: reply matched (T=0x285e7a20)!
Jan 20 14:39:21 [53020] DBG™️t_check: end=0x285e7a20
Jan 20 14:39:21 [53020] DBG™️reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jan 20 14:39:21 [53020] DBG™️t_should_relay_response: T_code=0, new_code=200
Jan 20 14:39:21 [53020] DBG™️relay_reply: branch=0, save=0, relay=0
Jan 20 14:39:21 [53020] DBG:core:build_res_buf_from_sip_res:  old size: 701, new size: 639
Jan 20 14:39:21 [53020] DBG:core:build_res_buf_from_sip_res: copied size: orig:78, new: 16, rest: 623 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.192.41:44010;received=192.168.192.41;branch=z9hG4bK-d87543-0261dc62e83ee57f-1--d87543-;rport=44010
From: "3790990"<sip:3790990@192.168.128.6>;tag=c8390f1b
To: "3790007"<sip:3790007@192.168.128.6>;tag=1c1404466542
Call-ID: NDkyODY3MjYwNTQxY2I1Yzg3OWZiODVkOTVkNGU0ODM.
CSeq: 3 BYE
Contact: <sip:1111122@192.168.131.2>
Record-Route: <sip:192.168.128.6;lr=on;ftag=c8390f1b;did=67f.9d807ae>
Supported: em,timer,replaces,path
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 2000/v.4.60A.028.003
Content-Length: 0

Jan 20 14:39:21 [53020] DBG:core:_shm_resize: resize(0) called
Jan 20 14:39:21 [53020] DBG™️insert_timer_unsafe: [2]: 0x285e7a68 (30)
Jan 20 14:39:21 [53020] DBG™️relay_reply: sent buf=0x81a8fc8: SIP/2.0 2..., shmem=0x285e9938: SIP/2.0 2
Jan 20 14:39:21 [53020] DBG™️cleanup_uac_timers: RETR/FR timers reset
Jan 20 14:39:21 [53020] DBG™️t_unref: UNREF_UNSAFE: after is 0
Jan 20 14:39:21 [53020] DBG:core:destroy_avp_list: destroying list 0x0
Jan 20 14:39:21 [53020] DBG:core:receive_msg: cleaning up
Jan 20 14:39:22 [53021] DBG™️utimer_routine: timer routine:4,tl=0x285e7b6c next=0x0, timeout=22800000
^CJan 20 14:39:23 [53020] DBG:core:handle_sigs: INT received, program terminates
Jan 20 14:39:23 [53022] INFO:core:sig_usr: signal 2 received
Jan 20 14:39:23 [53021] INFO:core:sig_usr: signal 15 received
Memory status (pkg):
fm_status (0x8182d80):
Jan 20 14:39:23 [53022] INFO:core:sig_usr: signal 15 received
heap size= 1048576
Memory status (pkg):
used= 124768, used+overhead=152240, free=896336
fm_status (0x8182d80):
max used (+overhead)= 152240
heap size= 1048576
dumping free list:
used= 133456, used+overhead=160632, free=887944
max used (+overhead)= 160632
dumping free list:
hash =   1 fragments no.:     1, unused:     0
                 bucket size:         8 -         8 (first         8)
hash = 2054 fragments no.:     1, unused:     0
                 bucket size:    524288 -   1048576 (first    896392)
TOTAL:      1 free fragments = 896392 free bytes
-----------------------------
hash = 2054 fragments no.:     1, unused:     0
                 bucket size:    524288 -   1048576 (first    887992)
TOTAL:      2 free fragments = 888000 free bytes
-----------------------------
Jan 20 14:39:23 [53020] DBG:core:pool_remove: connection still kept in the pool
Jan 20 14:39:23 [53020] DBG:core:pool_remove: connection still kept in the pool
Jan 20 14:39:23 [53020] DBG:core:pool_remove: connection still kept in the pool
Jan 20 14:39:23 [53020] DBG:xlog:destroy: destroy module...
Jan 20 14:39:23 [53020] DBG:core:pool_remove: connection still kept in the pool
Jan 20 14:39:23 [53020] DBG:core:pool_remove: connection still kept in the pool
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: tm_shutdown : start
Jan 20 14:39:23 [53020] DBG™️unlink_timer_lists: emptying DELETE list
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: emptying hash table
Jan 20 14:39:23 [53020] DBG™️run_trans_callbacks: trans=0x285e4ff0, callback type 2048, id 0 entered
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: releasing timers
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: removing semaphores
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: destroying callback lists
Jan 20 14:39:23 [53020] DBG™️tm_shutdown: tm_shutdown : done
Memory status (pkg):
fm_status (0x8182d80):
heap size= 1048576
used= 115824, used+overhead=143856, free=904720
max used (+overhead)= 157320
dumping free list:
hash =   1 fragments no.:    10, unused:     0
                 bucket size:         8 -         8 (first         8)
hash =   2 fragments no.:    33, unused:     0
                 bucket size:        16 -        16 (first        16)
hash =   3 fragments no.:     7, unused:     0
                 bucket size:        24 -        24 (first        24)
hash =   4 fragments no.:    29, unused:     0
                 bucket size:        32 -        32 (first        32)
hash =   5 fragments no.:    20, unused:     0
                 bucket size:        40 -        40 (first        40)
hash =   6 fragments no.:     1, unused:     0
                 bucket size:        48 -        48 (first        48)
hash =   8 fragments no.:     1, unused:     0
                 bucket size:        64 -        64 (first        64)
hash =   9 fragments no.:     1, unused:     0
                 bucket size:        72 -        72 (first        72)
hash =  10 fragments no.:     1, unused:     0
                 bucket size:        80 -        80 (first        80)
hash =  14 fragments no.:     1, unused:     0
                 bucket size:       112 -       112 (first       112)
hash =  15 fragments no.:     1, unused:     0
                 bucket size:       120 -       120 (first       120)
hash =  27 fragments no.:     2, unused:     0
                 bucket size:       216 -       216 (first       216)
hash = 101 fragments no.:     1, unused:     0
                 bucket size:       808 -       808 (first       808)
hash = 128 fragments no.:     1, unused:     0
                 bucket size:      1024 -      1024 (first      1024)
hash = 1025 fragments no.:     1, unused:     0
                 bucket size:      8200 -      8200 (first      8200)
hash = 2054 fragments no.:     1, unused:     0
                 bucket size:    524288 -   1048576 (first    891312)
TOTAL:    111 free fragments = 904776 free bytes
-----------------------------
Memory status (shm):
fm_status (0x28445000):
heap size= 33554432
used= 16, used+overhead=17872, free=33536560
max used (+overhead)= 1722976
dumping free list:
hash =   1 fragments no.:    58, unused:     0
                 bucket size:         8 -         8 (first         8)
hash =   2 fragments no.:    10, unused:     0
                 bucket size:        16 -        16 (first        16)
hash =   3 fragments no.:     6, unused:     0
                 bucket size:        24 -        24 (first        24)
hash =   4 fragments no.:    49, unused:     0
                 bucket size:        32 -        32 (first        32)
hash =   5 fragments no.:     3, unused:     0
                 bucket size:        40 -        40 (first        40)
hash =   6 fragments no.:     3, unused:     0
                 bucket size:        48 -        48 (first        48)
hash =   8 fragments no.:     4, unused:     0
                 bucket size:        64 -        64 (first        64)
hash =  12 fragments no.:     1, unused:     0
                 bucket size:        96 -        96 (first        96)
hash =  16 fragments no.:     1, unused:     0
                 bucket size:       128 -       128 (first       128)
hash =  18 fragments no.:     1, unused:     0
                 bucket size:       144 -       144 (first       144)
hash =  21 fragments no.:     1, unused:     0
                 bucket size:       168 -       168 (first       168)
hash =  32 fragments no.:     1, unused:     0
                 bucket size:       256 -       256 (first       256)
hash =  44 fragments no.:     1, unused:     0
                 bucket size:       352 -       352 (first       352)
hash =  53 fragments no.:     1, unused:     0
                 bucket size:       424 -       424 (first       424)
hash =  64 fragments no.:     1, unused:     0
                 bucket size:       512 -       512 (first       512)
hash =  80 fragments no.:     1, unused:     0
                 bucket size:       640 -       640 (first       640)
hash = 114 fragments no.:     1, unused:     0
                 bucket size:       912 -       912 (first       912)
hash = 130 fragments no.:     1, unused:     0
                 bucket size:      1040 -      1040 (first      1040)
hash = 132 fragments no.:     1, unused:     0
                 bucket size:      1056 -      1056 (first      1056)
hash = 144 fragments no.:     1, unused:     0
                 bucket size:      1152 -      1152 (first      1152)
hash = 174 fragments no.:     1, unused:     0
                 bucket size:      1392 -      1392 (first      1392)
hash = 257 fragments no.:     1, unused:     0
                 bucket size:      2056 -      2056 (first      2056)
hash = 421 fragments no.:     1, unused:     0
                 bucket size:      3368 -      3368 (first      3368)
hash = 457 fragments no.:     2, unused:     0
                 bucket size:      3656 -      3656 (first      3656)
hash = 505 fragments no.:     1, unused:     0
                 bucket size:      4040 -      4040 (first      4040)
hash = 512 fragments no.:     2, unused:     0
                 bucket size:      4096 -      4096 (first      4096)
hash = 1025 fragments no.:     1, unused:     0
                 bucket size:      8200 -      8200 (first      8200)
hash = 1280 fragments no.:     1, unused:     0
                 bucket size:     10240 -     10240 (first     10240)
hash = 1563 fragments no.:     1, unused:     0
                 bucket size:     12504 -     12504 (first     12504)
hash = 2051 fragments no.:     1, unused:     0
                 bucket size:     65536 -    131072 (first     65552)
hash = 2055 fragments no.:     1, unused:     0
                 bucket size:   1048576 -   2097152 (first   1572864)
hash = 2059 fragments no.:     1, unused:     0
                 bucket size:  16777216 -  33554432 (first  31831104)
TOTAL:    160 free fragments = 33536560 free bytes
-----------------------------
Jan 20 14:39:23 [53020] DBG:core:shm_mem_destroy:
Jan 20 14:39:23 [53020] DBG:core:shm_mem_destroy: destroying the shared memory lock
Thank you for flying opensips