dialog.so: dialog don't finished with BYE

[Nobody/Anonymous]

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

[Nobody/Anonymous]

PS Sorry for my English.

[Bogdan-Andrei Iancu]

Do you do record_route() for the INVITE and loose_route() for the BYE?

Regards,
Bogdan

[Herman]

I'm having the same problem with Opensips 1.4.2-notls. When a call is set up, and released within five seconds, the dialog is not removed. I am sure the call is set up correctly (INVITE - 200 OK - ACK) and the BYE is sent (with the correct call-id, from and to tag), but the dialog is not removed.

I do a record_route_preset () for the INVITE and a loose_route() for the BYE.

Are there any timers, caching, ... that could explain this behavior? I have tested a number of times, and the problem only occurs if the call is shut down within the first five seconds, if the call is running longer, the dialog is cleaned up correctly when the BYE is sent.

note: a dialog is inserted multiple times in the same profile, but with different values, I don't know if this is relevant for the issue

[Bogdan-Andrei Iancu]

So, let me see if I get it right. With the same configuration, if the call is longer than 5 secs, everything is ok (dialog is removed when receiving a BYE). But if the call is shorter than 5 secs, the dialog is not removed.

Is this what you say?

Regards.
Bogdan