Feb 6 10:44:59 [8321] DBG:core:parse_msg: SIP Request: Feb 6 10:44:59 [8321] DBG:core:parse_msg: method: Feb 6 10:44:59 [8321] DBG:core:parse_msg: uri: Feb 6 10:44:59 [8321] DBG:core:parse_msg: version: Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=2 Feb 6 10:44:59 [8321] DBG:core:get_hdr_field: cseq : <1> Feb 6 10:44:59 [8321] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:44:59 [8321] DBG:core:parse_via_param: found param type 235, = ; state=17 Feb 6 10:44:59 [8321] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:44:59 [8321] DBG:core:parse_headers: via found, flags=2 Feb 6 10:44:59 [8321] DBG:core:parse_headers: this is the first via Feb 6 10:44:59 [8321] DBG:core:receive_msg: After parse_msg... Feb 6 10:44:59 [8321] DBG:core:receive_msg: preparing to run routing scripts... Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=10 Feb 6 10:44:59 [8321] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:44:59 [8321] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:44:59 [8321] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=8 Feb 6 10:44:59 [8321] DBG:core:parse_to: end of header reached, state=10 Feb 6 10:44:59 [8321] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:44:59 [8321] DBG:core:get_hdr_field: [31]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:44:59 [8321] DBG:core:get_hdr_field: to body [ ] New request - M=INVITE RURI=sip:600@voip.leotelecom.net F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=100 Feb 6 10:44:59 [8321] DBG:core:get_hdr_field: content_length=304 Feb 6 10:44:59 [8321] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 6 10:44:59 [8321] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=80 Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=200 Feb 6 10:44:59 [8321] DBG:core:get_hdr_field: found end of header Feb 6 10:44:59 [8321] DBG:rr:find_first_route: No Route headers found Feb 6 10:44:59 [8321] DBG:rr:loose_route: There is no Route HF Feb 6 10:44:59 [8321] DBG:sst:sst_check_min: No Session-Expires header found. retuning false (-1) Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 8 chars, out: 8 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfaf10 PQsendQuery(select grp from grp where username='100' AND grp='disabled' AND domain='voip.leotelecom.net') Feb 6 10:44:59 [8321] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfaf10 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6970) Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:44:59 [8321] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:44:59 [8321] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6970) result set Feb 6 10:44:59 [8321] DBG:group:is_user_in: user is not in group 'disabled' Feb 6 10:44:59 [8321] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:44:59 [8321] DBG:core:db_free_result: freeing result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 11 chars, out: 11 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfaf10 PQsendQuery(select grp from grp where username='100' AND grp='deactivated' AND domain='voip.leotelecom.net') Feb 6 10:44:59 [8321] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfaf10 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6970) Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:44:59 [8321] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:44:59 [8321] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6970) result set Feb 6 10:44:59 [8321] DBG:group:is_user_in: user is not in group 'deactivated' Feb 6 10:44:59 [8321] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:44:59 [8321] DBG:core:db_free_result: freeing result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 8 chars, out: 8 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfaf10 PQsendQuery(select grp from grp where username='600' AND grp='disabled' AND domain='voip.leotelecom.net') Feb 6 10:44:59 [8321] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfaf10 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6970) Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:44:59 [8321] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:44:59 [8321] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6970) result set Feb 6 10:44:59 [8321] DBG:group:is_user_in: user is not in group 'disabled' Feb 6 10:44:59 [8321] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:44:59 [8321] DBG:core:db_free_result: freeing result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 11 chars, out: 11 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfaf10 PQsendQuery(select grp from grp where username='600' AND grp='deactivated' AND domain='voip.leotelecom.net') Feb 6 10:44:59 [8321] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfaf10 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6970) Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:44:59 [8321] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:44:59 [8321] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:44:59 [8321] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6970) result set Feb 6 10:44:59 [8321] DBG:group:is_user_in: user is not in group 'deactivated' Feb 6 10:44:59 [8321] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:44:59 [8321] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:44:59 [8321] DBG:core:db_free_result: freeing result set at 0x7fb0eedfefc0 Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:44:59 [8321] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=10000 Feb 6 10:44:59 [8321] DBG:auth:pre_auth: credentials with given realm not found Proxy authentication failed - M=INVITE RURI=sip:600@voip.leotelecom.net F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:44:59 [8321] DBG:auth:reserve_nonce_index: second= 91, sec_monit= -1, index= 2 Feb 6 10:44:59 [8321] DBG:auth:build_auth_hf: nonce index= 2 Feb 6 10:44:59 [8321] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="voip.leotelecom.net", nonce="498bf9b700000002e5e2ed952a3f27668035756eff9f3ebe" ' Feb 6 10:44:59 [8321] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:44:59 [8321] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:44:59 [8321] DBG:core:destroy_avp_list: destroying list (nil) Feb 6 10:44:59 [8321] DBG:core:receive_msg: cleaning up Feb 6 10:44:59 [8324] DBG:core:parse_msg: SIP Request: Feb 6 10:44:59 [8324] DBG:core:parse_msg: method: Feb 6 10:44:59 [8324] DBG:core:parse_msg: uri: Feb 6 10:44:59 [8324] DBG:core:parse_msg: version: Feb 6 10:44:59 [8324] DBG:core:parse_headers: flags=2 Feb 6 10:44:59 [8324] DBG:core:get_hdr_field: cseq : <1> Feb 6 10:44:59 [8324] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:44:59 [8324] DBG:core:parse_via_param: found param type 235, = ; state=17 Feb 6 10:44:59 [8324] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:44:59 [8324] DBG:core:parse_headers: via found, flags=2 Feb 6 10:44:59 [8324] DBG:core:parse_headers: this is the first via Feb 6 10:44:59 [8324] DBG:core:receive_msg: After parse_msg... Feb 6 10:44:59 [8324] DBG:core:receive_msg: preparing to run routing scripts... Feb 6 10:44:59 [8324] DBG:core:parse_headers: flags=8 Feb 6 10:44:59 [8324] DBG:core:parse_to_param: tag=5e7d7a888116f0752b1b6010d2f21ec5.0e3f Feb 6 10:44:59 [8324] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:44:59 [8324] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:44:59 [8324] DBG:core:get_hdr_field: [73]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:44:59 [8324] DBG:core:get_hdr_field: to body [] Feb 6 10:44:59 [8324] DBG:sl:sl_filter_ACK: local ACK found -> dropping it! Feb 6 10:44:59 [8324] DBG:core:destroy_avp_list: destroying list (nil) Feb 6 10:44:59 [8324] DBG:core:receive_msg: cleaning up Feb 6 10:44:59 [8336] DBG:core:parse_msg: SIP Request: Feb 6 10:44:59 [8336] DBG:core:parse_msg: method: Feb 6 10:44:59 [8336] DBG:core:parse_msg: uri: Feb 6 10:44:59 [8336] DBG:core:parse_msg: version: Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=2 Feb 6 10:44:59 [8336] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:44:59 [8336] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:44:59 [8336] DBG:core:parse_via_param: found param type 235, = ; state=17 Feb 6 10:44:59 [8336] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:44:59 [8336] DBG:core:parse_headers: via found, flags=2 Feb 6 10:44:59 [8336] DBG:core:parse_headers: this is the first via Feb 6 10:44:59 [8336] DBG:core:receive_msg: After parse_msg... Feb 6 10:44:59 [8336] DBG:core:receive_msg: preparing to run routing scripts... Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=10 Feb 6 10:44:59 [8336] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:44:59 [8336] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:44:59 [8336] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=8 Feb 6 10:44:59 [8336] DBG:core:parse_to: end of header reached, state=10 Feb 6 10:44:59 [8336] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:44:59 [8336] DBG:core:get_hdr_field: [31]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:44:59 [8336] DBG:core:get_hdr_field: to body [ ] New request - M=INVITE RURI=sip:600@voip.leotelecom.net F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=100 Feb 6 10:44:59 [8336] DBG:core:get_hdr_field: content_length=304 Feb 6 10:44:59 [8336] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 6 10:44:59 [8336] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=80 Feb 6 10:44:59 [8336] DBG:core:parse_headers: flags=200 Feb 6 10:44:59 [8336] DBG:core:get_hdr_field: found end of header Feb 6 10:44:59 [8336] DBG:rr:find_first_route: No Route headers found Feb 6 10:44:59 [8336] DBG:rr:loose_route: There is no Route HF Feb 6 10:44:59 [8336] DBG:sst:sst_check_min: No Session-Expires header found. retuning false (-1) Feb 6 10:44:59 [8336] ERROR:core:pv_parse_spec: bad parameters Feb 6 10:44:59 [8336] ERROR:group:get_hf: unsupported User Field identifier Feb 6 10:45:00 [8323] DBG:core:udp_rcv_loop: probing packet received from 194.44.160.178 50963 Feb 6 10:45:00 [8323] DBG:core:udp_rcv_loop: probing packet received from 194.44.160.178 51219 Feb 6 10:45:00 [8322] DBG:core:parse_msg: SIP Request: Feb 6 10:45:00 [8322] DBG:core:parse_msg: method: Feb 6 10:45:00 [8322] DBG:core:parse_msg: uri: Feb 6 10:45:00 [8322] DBG:core:parse_msg: version: Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=2 Feb 6 10:45:00 [8322] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:45:00 [8322] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:00 [8322] DBG:core:parse_via_param: found param type 235, = ; state=17 Feb 6 10:45:00 [8322] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:00 [8322] DBG:core:parse_headers: via found, flags=2 Feb 6 10:45:00 [8322] DBG:core:parse_headers: this is the first via Feb 6 10:45:00 [8322] DBG:core:receive_msg: After parse_msg... Feb 6 10:45:00 [8322] DBG:core:receive_msg: preparing to run routing scripts... Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=10 Feb 6 10:45:00 [8322] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:45:00 [8322] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:00 [8322] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=8 Feb 6 10:45:00 [8322] DBG:core:parse_to: end of header reached, state=10 Feb 6 10:45:00 [8322] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:45:00 [8322] DBG:core:get_hdr_field: [31]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:45:00 [8322] DBG:core:get_hdr_field: to body [ ] New request - M=INVITE RURI=sip:600@voip.leotelecom.net F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=100 Feb 6 10:45:00 [8322] DBG:core:get_hdr_field: content_length=304 Feb 6 10:45:00 [8322] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 6 10:45:00 [8322] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=80 Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=200 Feb 6 10:45:00 [8322] DBG:core:get_hdr_field: found end of header Feb 6 10:45:00 [8322] DBG:rr:find_first_route: No Route headers found Feb 6 10:45:00 [8322] DBG:rr:loose_route: There is no Route HF Feb 6 10:45:00 [8322] DBG:sst:sst_check_min: No Session-Expires header found. retuning false (-1) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 8 chars, out: 8 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcec0 PQsendQuery(select grp from grp where username='100' AND grp='disabled' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcec0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6ae0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6ae0) result set Feb 6 10:45:00 [8322] DBG:group:is_user_in: user is not in group 'disabled' Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 11 chars, out: 11 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcec0 PQsendQuery(select grp from grp where username='100' AND grp='deactivated' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcec0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6ae0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6ae0) result set Feb 6 10:45:00 [8322] DBG:group:is_user_in: user is not in group 'deactivated' Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 8 chars, out: 8 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcec0 PQsendQuery(select grp from grp where username='600' AND grp='disabled' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcec0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6ae0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6ae0) result set Feb 6 10:45:00 [8322] DBG:group:is_user_in: user is not in group 'disabled' Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 11 chars, out: 11 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcec0 PQsendQuery(select grp from grp where username='600' AND grp='deactivated' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcec0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeef6ae0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[grp] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeef6ae0) result set Feb 6 10:45:00 [8322] DBG:group:is_user_in: user is not in group 'deactivated' Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:45:00 [8322] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:45:00 [8322] DBG:auth:check_nonce: comparing [498bf9b700000002e5e2ed952a3f27668035756eff9f3ebe] and [498bf9b700000002e5e2ed952a3f27668035756eff9f3ebe] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcdb0 PQsendQuery(select password,rpid from subscriber where username='100' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcdb0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeeff8b0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 2 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x7fb0eedd8758 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8770)[0]=[password] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8780)[1]=[rpid] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: allocate for 2 columns 16 bytes in row buffer at 0x7fb0eedd9d98 Feb 6 10:45:00 [8322] DBG:core:db_allocate_rows: allocate 80 bytes for result rows and values at 0x7fb0eedd9db8 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x7fb0eedfcdb0,0,0)=[100voip] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: allocated 7 bytes for row_buf[0] at 0x7fb0eedfedc0 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: [0][0] Column[password]=[100voip] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x7fb0eedfcdb0,0,1)=[] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[1] at 0x7fb0eedfedd8 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: [0][1] Column[rpid]=[] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_str2val: converting STRING [100voip] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_str2val: converting STRING [] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: freeing row buffer at 0x7fb0eedd9d98 Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeeff8b0) result set Feb 6 10:45:00 [8322] DBG:auth_db:get_ha1: HA1 string calculated: bd4264a3b45ec4b3baaf4042e2dd6705 Feb 6 10:45:00 [8322] DBG:auth:check_response: our result = 'fecc4459224e2237dd823ca7923061d8' Feb 6 10:45:00 [8322] DBG:auth:check_response: authorization is OK Feb 6 10:45:00 [8322] DBG:auth:post_auth: nonce index= 2 Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8758 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 1 rows Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing rows at 0x7fb0eedd9db8 Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:uri_db:check_username: Digest username and URI username match Feb 6 10:45:00 [8322] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=80 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfcfd0 PQsendQuery(select username from subscriber where username='600' AND domain='voip.leotelecom.net') Feb 6 10:45:00 [8322] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfeb10 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_store_result: 0x7fb0eedfcfd0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x7fb0eeeff8b0) Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: 1 columns returned from the query Feb 6 10:45:00 [8322] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: RES_NAMES(0x7fb0eedd8734)[0]=[username] Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_get_columns: use DB_STRING result type Feb 6 10:45:00 [8322] DBG:db_postgres:db_postgres_convert_rows: no rows returned from the query Feb 6 10:45:00 [8322] DBG:db_postgres:free_query: PQclear(0x7fb0eeeff8b0) result set Feb 6 10:45:00 [8322] DBG:uri_db:does_uri_exist: User in request uri does not exist Feb 6 10:45:00 [8322] DBG:core:db_free_columns: freeing result columns at 0x7fb0eedd8728 Feb 6 10:45:00 [8322] DBG:core:db_free_rows: freeing 0 rows Feb 6 10:45:00 [8322] DBG:core:db_free_result: freeing result set at 0x7fb0eedfeb10 Callee is on Media server - M=INVITE RURI=sip:600@voip.leotelecom.net F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=ffffffffffffffff Setting acc source-leg - M=INVITE RURI=sip:600@voip.leotelecom.net:5061 F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Setting acc destination-leg - M=INVITE RURI=sip:600@voip.leotelecom.net:5061 F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8322] DBG:core:pv_get_dsturi: no destination URI Request leaving server, D-URI='' - M=INVITE RURI=sip:600@voip.leotelecom.net:5061 F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8322] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=78 Feb 6 10:45:00 [8322] DBG:tm:t_lookup_request: start searching: hash=26882, isACK=0 Feb 6 10:45:00 [8322] DBG:tm:matching_3261: RFC3261 transaction matching failed Feb 6 10:45:00 [8322] DBG:tm:t_lookup_request: no transaction found Feb 6 10:45:00 [8322] DBG:tm:run_reqin_callbacks: trans=0x7fb0c9b959e0, callback type 1, id 1 entered Feb 6 10:45:00 [8322] DBG:core:parse_headers: flags=78 Feb 6 10:45:00 [8322] DBG:rr:is_direction: param ftag not found Feb 6 10:45:00 [8322] DBG:tm:run_reqin_callbacks: trans=0x7fb0c9b959e0, callback type 1, id 0 entered Feb 6 10:45:00 [8322] DBG:core:mk_proxy: doing DNS lookup... Feb 6 10:45:00 [8322] DBG:core:sip_resolvehost: has port -> do A record lookup! Feb 6 10:45:00 [8322] DBG:core:get_out_socket: socket determined: 0x7fb0eedc0af0 Feb 6 10:45:00 [8322] DBG:tm:set_timer: relative timeout is 500000 Feb 6 10:45:00 [8322] DBG:tm:insert_timer_unsafe: [4]: 0x7fb0c9b95be0 (92600000) Feb 6 10:45:00 [8322] DBG:tm:set_timer: relative timeout is 10 Feb 6 10:45:00 [8322] DBG:tm:insert_timer_unsafe: [0]: 0x7fb0c9b95c10 (102) Feb 6 10:45:00 [8322] DBG:tm:t_relay_to: new transaction fwd'ed Feb 6 10:45:00 [8322] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 6 10:45:00 [8322] DBG:core:destroy_avp_list: destroying list (nil) Feb 6 10:45:00 [8322] DBG:core:receive_msg: cleaning up Feb 6 10:45:00 [8335] DBG:core:parse_msg: SIP Reply (status): Feb 6 10:45:00 [8335] DBG:core:parse_msg: version: Feb 6 10:45:00 [8335] DBG:core:parse_msg: status: <100> Feb 6 10:45:00 [8335] DBG:core:parse_msg: reason: Feb 6 10:45:00 [8335] DBG:core:parse_headers: flags=2 Feb 6 10:45:00 [8335] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:00 [8335] DBG:core:parse_via_param: found param type 234, = <194.44.160.58>; state=16 Feb 6 10:45:00 [8335] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:00 [8324] DBG:core:parse_msg: SIP Reply (status): Feb 6 10:45:00 [8335] DBG:core:parse_headers: via found, flags=2 Feb 6 10:45:00 [8324] DBG:core:parse_msg: version: Feb 6 10:45:00 [8335] DBG:core:parse_headers: this is the first via Feb 6 10:45:00 [8324] DBG:core:parse_msg: status: <183> Feb 6 10:45:00 [8335] DBG:core:receive_msg: After parse_msg... Feb 6 10:45:00 [8324] DBG:core:parse_msg: reason: Feb 6 10:45:00 [8335] DBG:core:forward_reply: found module tm, passing reply to it Feb 6 10:45:00 [8324] DBG:core:parse_headers: flags=2 Feb 6 10:45:00 [8335] DBG:tm:t_check: start=0xffffffffffffffff Feb 6 10:45:00 [8324] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:00 [8335] DBG:core:parse_headers: flags=22 Feb 6 10:45:00 [8324] DBG:core:parse_via_param: found param type 234, = <194.44.160.58>; state=16 Feb 6 10:45:00 [8335] DBG:core:parse_via_param: found param type 234, = <194.44.160.178>; state=6 Feb 6 10:45:00 [8324] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:00 [8335] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:00 [8324] DBG:core:parse_headers: via found, flags=2 Feb 6 10:45:00 [8335] DBG:core:parse_via_param: found param type 235, = <5084>; state=16 Feb 6 10:45:00 [8324] DBG:core:parse_headers: this is the first via Feb 6 10:45:00 [8324] DBG:core:receive_msg: After parse_msg... Feb 6 10:45:00 [8324] DBG:core:forward_reply: found module tm, passing reply to it Feb 6 10:45:00 [8335] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:00 [8324] DBG:tm:t_check: start=0xffffffffffffffff Feb 6 10:45:00 [8335] DBG:core:parse_headers: via found, flags=22 Feb 6 10:45:00 [8324] DBG:core:parse_headers: flags=22 Feb 6 10:45:00 [8335] DBG:core:parse_headers: parse_headers: this is the second via Feb 6 10:45:00 [8324] DBG:core:parse_via_param: found param type 234, = <194.44.160.178>; state=6 Feb 6 10:45:00 [8335] DBG:core:parse_to: end of header reached, state=10 Feb 6 10:45:00 [8324] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:00 [8335] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:45:00 [8324] DBG:core:parse_via_param: found param type 235, = <5084>; state=16 Feb 6 10:45:00 [8335] DBG:core:get_hdr_field: [31]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:45:00 [8324] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:00 [8335] DBG:core:get_hdr_field: to body [ ] Feb 6 10:45:00 [8324] DBG:core:parse_headers: via found, flags=22 Feb 6 10:45:00 [8335] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:45:00 [8324] DBG:core:parse_headers: parse_headers: this is the second via Feb 6 10:45:00 [8335] DBG:core:parse_headers: flags=8 Feb 6 10:45:00 [8324] DBG:core:parse_to_param: tag=as36703cac Feb 6 10:45:00 [8335] DBG:tm:t_reply_matching: hash 26882 label 75310899 branch 0 Feb 6 10:45:00 [8324] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:00 [8335] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Feb 6 10:45:00 [8324] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:45:00 [8335] DBG:tm:t_reply_matching: reply matched (T=0x7fb0c9b959e0)! Feb 6 10:45:00 [8324] DBG:core:get_hdr_field: [46]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:45:00 [8335] DBG:tm:run_trans_callbacks: trans=0x7fb0c9b959e0, callback type 2, id 0 entered Feb 6 10:45:00 [8324] DBG:core:get_hdr_field: to body [] Feb 6 10:45:00 [8335] DBG:tm:t_check: end=0x7fb0c9b959e0 Feb 6 10:45:00 [8324] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:45:00 [8335] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1) Feb 6 10:45:00 [8324] DBG:core:parse_headers: flags=8 Feb 6 10:45:00 [8335] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:45:00 [8324] DBG:tm:t_reply_matching: hash 26882 label 75310899 branch 0 Feb 6 10:45:00 [8335] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:00 [8324] DBG:tm:t_reply_matching: REF_UNSAFE: after is 2 Feb 6 10:45:00 [8335] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Feb 6 10:45:00 [8324] DBG:tm:t_reply_matching: reply matched (T=0x7fb0c9b959e0)! Reply - S=100 D=Trying F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.58 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8324] DBG:tm:run_trans_callbacks: trans=0x7fb0c9b959e0, callback type 2, id 0 entered Feb 6 10:45:00 [8335] DBG:tm:t_should_relay_response: T_code=0, new_code=100 Feb 6 10:45:00 [8324] DBG:tm:t_check: end=0x7fb0c9b959e0 Feb 6 10:45:00 [8335] DBG:tm:relay_reply: branch=0, save=0, relay=-1 Feb 6 10:45:00 [8324] DBG:tm:reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1) Feb 6 10:45:00 [8335] DBG:tm:set_timer: relative timeout is 30 Feb 6 10:45:00 [8324] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:45:00 [8335] DBG:tm:insert_timer_unsafe: [1]: 0x7fb0c9b95c10 (122) Feb 6 10:45:00 [8324] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:00 [8335] DBG:tm:t_unref: UNREF_UNSAFE: after is 1 Feb 6 10:45:00 [8324] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Feb 6 10:45:00 [8335] DBG:core:destroy_avp_list: destroying list (nil) Reply - S=183 D=Session Progress F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.58 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:00 [8335] DBG:core:receive_msg: cleaning up Feb 6 10:45:00 [8324] DBG:tm:t_should_relay_response: T_code=0, new_code=183 Feb 6 10:45:00 [8324] DBG:tm:relay_reply: branch=0, save=0, relay=0 Feb 6 10:45:00 [8324] DBG:core:build_res_buf_from_sip_res: old size: 1058, new size: 974 Feb 6 10:45:00 [8324] DBG:core:build_res_buf_from_sip_res: copied size: orig:114, new: 30, rest: 944 msg= SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 194.44.160.178:5084;received=194.44.160.178;branch=z9hG4bK4af7471b-98f2-dd11-9564-001fc6030555;rport=5084 Record-Route: From: "Oleksandr Panchuk" ;tag=b4b8681a-98f2-dd11-9564-001fc6030555 To: ;tag=as36703cac Call-ID: 9eb5681a-98f2-dd11-9564-001fc6030555@olex CSeq: 2 INVITE User-Agent: LeoTelecom IVR Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 304 v=0 o=root 321748312 321748312 IN IP4 194.44.160.58 s=LeoTelecom IVR c=IN IP4 194.44.160.58 t=0 0 m=audio 17950 RTP/AVP 3 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv Feb 6 10:45:00 [8324] DBG:core:_shm_resize: resize(0) called Feb 6 10:45:00 [8324] DBG:tm:relay_reply: sent buf=0x7fb0eedfe5c8: SIP/2.0 1..., shmem=0x7fb0c9b99358: SIP/2.0 1 Feb 6 10:45:00 [8324] DBG:tm:run_trans_callbacks: trans=0x7fb0c9b959e0, callback type 128, id 0 entered Feb 6 10:45:00 [8324] DBG:tm:set_timer: relative timeout is 30 Feb 6 10:45:00 [8324] DBG:tm:insert_timer_unsafe: [1]: 0x7fb0c9b95c10 (122) Feb 6 10:45:00 [8324] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 6 10:45:00 [8324] DBG:core:destroy_avp_list: destroying list (nil) Feb 6 10:45:00 [8324] DBG:core:receive_msg: cleaning up Feb 6 10:45:00 [8341] DBG:tm:utimer_routine: timer routine:4,tl=0x7fb0c9b95be0 next=(nil), timeout=92600000 Feb 6 10:45:01 [8323] DBG:core:parse_msg: SIP Reply (status): Feb 6 10:45:01 [8323] DBG:core:parse_msg: version: Feb 6 10:45:01 [8323] DBG:core:parse_msg: status: <200> Feb 6 10:45:01 [8323] DBG:core:parse_msg: reason: Feb 6 10:45:01 [8323] DBG:core:parse_headers: flags=2 Feb 6 10:45:01 [8323] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:01 [8323] DBG:core:parse_via_param: found param type 234, = <194.44.160.58>; state=16 Feb 6 10:45:01 [8323] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:01 [8323] DBG:core:parse_headers: via found, flags=2 Feb 6 10:45:01 [8323] DBG:core:parse_headers: this is the first via Feb 6 10:45:01 [8323] DBG:core:receive_msg: After parse_msg... Feb 6 10:45:01 [8323] DBG:core:forward_reply: found module tm, passing reply to it Feb 6 10:45:01 [8323] DBG:tm:t_check: start=0xffffffffffffffff Feb 6 10:45:01 [8323] DBG:core:parse_headers: flags=22 Feb 6 10:45:01 [8323] DBG:core:parse_via_param: found param type 234, = <194.44.160.178>; state=6 Feb 6 10:45:01 [8323] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:01 [8323] DBG:core:parse_via_param: found param type 235, = <5084>; state=16 Feb 6 10:45:01 [8323] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:01 [8323] DBG:core:parse_headers: via found, flags=22 Feb 6 10:45:01 [8323] DBG:core:parse_headers: parse_headers: this is the second via Feb 6 10:45:01 [8323] DBG:core:parse_to_param: tag=as36703cac Feb 6 10:45:01 [8323] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:01 [8323] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:45:01 [8323] DBG:core:get_hdr_field: [46]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:45:01 [8323] DBG:core:get_hdr_field: to body [] Feb 6 10:45:01 [8323] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:45:01 [8323] DBG:core:parse_headers: flags=8 Feb 6 10:45:01 [8323] DBG:tm:t_reply_matching: hash 26882 label 75310899 branch 0 Feb 6 10:45:01 [8323] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Feb 6 10:45:01 [8323] DBG:tm:t_reply_matching: reply matched (T=0x7fb0c9b959e0)! Feb 6 10:45:01 [8323] DBG:core:parse_headers: flags=8 Feb 6 10:45:01 [8323] DBG:tm:run_trans_callbacks: trans=0x7fb0c9b959e0, callback type 2, id 0 entered Feb 6 10:45:01 [8323] DBG:core:parse_headers: flags=8 Feb 6 10:45:01 [8323] DBG:tm:t_check: end=0x7fb0c9b959e0 Feb 6 10:45:01 [8323] DBG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1) Feb 6 10:45:01 [8323] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:45:01 [8323] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:01 [8323] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} Reply - S=200 D=OK F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.58 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:01 [8323] DBG:tm:t_should_relay_response: T_code=183, new_code=200 Feb 6 10:45:01 [8323] DBG:tm:relay_reply: branch=0, save=0, relay=0 Feb 6 10:45:01 [8323] DBG:core:build_res_buf_from_sip_res: old size: 1044, new size: 960 Feb 6 10:45:01 [8323] DBG:core:build_res_buf_from_sip_res: copied size: orig:100, new: 16, rest: 944 msg= SIP/2.0 200 OK Via: SIP/2.0/UDP 194.44.160.178:5084;received=194.44.160.178;branch=z9hG4bK4af7471b-98f2-dd11-9564-001fc6030555;rport=5084 Record-Route: From: "Oleksandr Panchuk" ;tag=b4b8681a-98f2-dd11-9564-001fc6030555 To: ;tag=as36703cac Call-ID: 9eb5681a-98f2-dd11-9564-001fc6030555@olex CSeq: 2 INVITE User-Agent: LeoTelecom IVR Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 304 v=0 o=root 321748312 321748313 IN IP4 194.44.160.58 s=LeoTelecom IVR c=IN IP4 194.44.160.58 t=0 0 m=audio 17950 RTP/AVP 3 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv Feb 6 10:45:01 [8323] DBG:tm:update_totag_set: new totag Feb 6 10:45:01 [8323] DBG:tm:insert_timer_unsafe: [2]: 0x7fb0c9b95a60 (97) Feb 6 10:45:01 [8323] DBG:tm:relay_reply: sent buf=0x7fb0eedfedb0: SIP/2.0 2..., shmem=0x7fb0c9b99358: SIP/2.0 2 Feb 6 10:45:01 [8323] DBG:tm:run_trans_callbacks: trans=0x7fb0c9b959e0, callback type 128, id 0 entered Feb 6 10:45:01 [8323] DBG:core:pv_get_dsturi_attr: no destination URI Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 6 chars, out: 6 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 36 chars, out: 36 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 10 chars, out: 10 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 41 chars, out: 41 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 2 chars, out: 2 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 19 chars, out: 19 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 3 chars, out: 3 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 0 chars, out: 0 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 28 chars, out: 28 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_val2str: PQescapeStringConn: in: 23 chars, out: 23 chars Feb 6 10:45:01 [8323] DBG:db_postgres:db_postgres_submit_query: 0x7fb0eedfd0e0 PQsendQuery(insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time,caller_num,caller_domain,callee_num,callee_domain,src_leg,dst_leg ) values ('INVITE','b4b8681a-98f2-dd11-9564-001fc6030555','as36703cac','9eb5681a-98f2-dd11-9564-001fc6030555@olex','200','OK','2009-02-06 10:45:01','100','voip.leotelecom.net','600','','100|voip.leotelecom.net|call','600|voip.leotelecom.net')) Feb 6 10:45:01 [8323] DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb0eedfe388 Feb 6 10:45:01 [8338] DBG:core:parse_msg: SIP Request: Feb 6 10:45:01 [8338] DBG:core:parse_msg: method: Feb 6 10:45:01 [8338] DBG:core:parse_msg: uri: Feb 6 10:45:01 [8338] DBG:core:parse_msg: version: Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=2 Feb 6 10:45:01 [8338] DBG:core:get_hdr_field: cseq : <2> Feb 6 10:45:01 [8338] DBG:core:parse_via_param: found param type 232, = ; state=6 Feb 6 10:45:01 [8338] DBG:core:parse_via_param: found param type 235, = ; state=17 Feb 6 10:45:01 [8338] DBG:core:parse_via: end of header reached, state=5 Feb 6 10:45:01 [8338] DBG:core:parse_headers: via found, flags=2 Feb 6 10:45:01 [8338] DBG:core:parse_headers: this is the first via Feb 6 10:45:01 [8338] DBG:core:receive_msg: After parse_msg... Feb 6 10:45:01 [8338] DBG:core:receive_msg: preparing to run routing scripts... Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=8 Feb 6 10:45:01 [8338] DBG:core:parse_to_param: tag=as36703cac Feb 6 10:45:01 [8338] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:01 [8338] DBG:core:parse_to: display={}, ruri={sip:600@voip.leotelecom.net} Feb 6 10:45:01 [8338] DBG:core:get_hdr_field: [46]; uri=[sip:600@voip.leotelecom.net] Feb 6 10:45:01 [8338] DBG:core:get_hdr_field: to body [] Feb 6 10:45:01 [8338] DBG:core:parse_to_param: tag=b4b8681a-98f2-dd11-9564-001fc6030555 Feb 6 10:45:01 [8338] DBG:core:parse_to: end of header reached, state=29 Feb 6 10:45:01 [8338] DBG:core:parse_to: display={"Oleksandr Panchuk"}, ruri={sip:100@voip.leotelecom.net} New request - M=ACK RURI=sip:600@194.44.160.58:5061 F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=100 Feb 6 10:45:01 [8338] DBG:core:get_hdr_field: content_length=0 Feb 6 10:45:01 [8338] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 6 10:45:01 [8338] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=80 Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=200 Feb 6 10:45:01 [8338] DBG:rr:is_preloaded: is_preloaded: No Feb 6 10:45:01 [8338] DBG:core:grep_sock_info: checking if host==us: 13==13 && [194.44.160.58] == [194.44.160.58] Feb 6 10:45:01 [8338] DBG:core:grep_sock_info: checking if port 5060 matches port 5061 Feb 6 10:45:01 [8338] DBG:core:check_self: host != me Feb 6 10:45:01 [8338] DBG:core:grep_sock_info: checking if host==us: 13==13 && [194.44.160.58] == [194.44.160.58] Feb 6 10:45:01 [8338] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Feb 6 10:45:01 [8338] DBG:rr:after_loose: Topmost route URI: 'sip:194.44.160.58;lr=on;ftag=b4b8681a-98f2-dd11-9564-001fc6030555' is me Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=200 Feb 6 10:45:01 [8338] DBG:core:get_hdr_field: found end of header Feb 6 10:45:01 [8338] DBG:rr:find_next_route: No next Route HF found Feb 6 10:45:01 [8338] DBG:rr:after_loose: No next URI found Feb 6 10:45:01 [8338] DBG:rr:run_rr_callbacks: callback id 0 entered with Feb 6 10:45:01 [8338] DBG:dialog:dlg_onroute: Route param 'did' not found Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=48 Feb 6 10:45:01 [8338] DBG:dialog:internal_get_dlg: no dialog callid='9eb5681a-98f2-dd11-9564-001fc6030555@olex' found Feb 6 10:45:01 [8338] DBG:dialog:internal_get_dlg: no dialog callid='9eb5681a-98f2-dd11-9564-001fc6030555@olex' found Feb 6 10:45:01 [8338] DBG:dialog:get_dlg: no dialog callid='9eb5681a-98f2-dd11-9564-001fc6030555@olex' found Feb 6 10:45:01 [8338] DBG:dialog:dlg_onroute: Callid '9eb5681a-98f2-dd11-9564-001fc6030555@olex' not found Feb 6 10:45:01 [8338] DBG:uri:has_totag: totag found Feb 6 10:45:01 [8338] DBG:core:check_via_address: params 194.44.160.178, 194.44.160.178, 0 Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=80 Feb 6 10:45:01 [8338] DBG:core:pv_get_dsturi: no destination URI Request leaving server, D-URI='' - M=ACK RURI=sip:600@194.44.160.58:5061 F=sip:100@voip.leotelecom.net T=sip:600@voip.leotelecom.net IP=194.44.160.178 ID=9eb5681a-98f2-dd11-9564-001fc6030555@olex Feb 6 10:45:01 [8338] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=ffffffffffffffff Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=78 Feb 6 10:45:01 [8338] DBG:tm:t_lookup_request: start searching: hash=26882, isACK=1 Feb 6 10:45:01 [8338] DBG:core:parse_headers: flags=38 Feb 6 10:45:01 [8338] DBG:tm:t_lookup_request: REF_UNSAFE: after is 2 Feb 6 10:45:01 [8338] DBG:tm:t_lookup_request: e2e proxy ACK found Feb 6 10:45:01 [8338] DBG:tm:t_newtran: building branch for end2end ACK Feb 6 10:45:01 [8338] DBG:tm:t_relay_to: forwarding ACK Feb 6 10:45:01 [8338] DBG:core:mk_proxy: doing DNS lookup... Feb 6 10:45:01 [8338] DBG:core:get_out_socket: socket determined: 0x7fb0eedc0af0 Feb 6 10:45:01 [8338] DBG:core:forward_request: sending: ACK sip:600@194.44.160.58:5061 SIP/2.0 Record-Route: CSeq: 2 ACK Via: SIP/2.0/UDP 194.44.160.58;branch=z9hG4bK2096.3372d74.2 Via: SIP/2.0/UDP 194.44.160.178:5084;received=194.44.160.178;branch=z9hG4bKf641141c-98f2-dd11-9564-001fc6030555;rport=5084 From: "Oleksandr Panchuk" ;tag=b4b8681a-98f2-dd11-9564-001fc6030555 Call-ID: 9eb5681a-98f2-dd11-9564-001fc6030555@olex To: ;tag=as36703cac Contact: Proxy-Authorization: Digest username="100", realm="voip.leotelecom.net", nonce="498bf9b700000002e5e2ed952a3f27668035756eff9f3ebe", uri="sip:600@194.44.160.58:5061", algorithm=md5, response="fe5c0643671506f825053a2c9378dcac" Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Length: 0 Max-Forwards: 69 . Feb 6 10:45:01 [8338] DBG:core:forward_request: orig. len=801, new_len=898, proto=1 Feb 6 10:45:01 [8338] DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 1 Feb 6 10:45:01 [8338] DBG:core:destroy_avp_list: destroying list (nil) Feb 6 10:45:01 [8338] DBG:core:receive_msg: cleaning up Feb 6 10:45:01 [8293] INFO:core:handle_sigs: child process 8336 exited by a signal 11 Feb 6 10:45:01 [8293] INFO:core:handle_sigs: core was generated Feb 6 10:45:01 [8293] INFO:core:handle_sigs: terminating due to SIGCHLD Feb 6 10:45:01 [8322] INFO:core:sig_usr: signal 15 received Feb 6 10:45:01 [8355] INFO:core:sig_usr: signal 15 received Feb 6 10:45:01 [8348] INFO:core:sig_usr: signal 15 received Memory status (pkg): Memory status (pkg): fm_status (0x7fb0eedb8000): Feb 6 10:45:01 [8329] INFO:core:sig_usr: signal 15 received Feb 6 10:45:01 [8358] INFO:core:sig_usr: signal 15 received Memory status (pkg): fm_status (0x7fb0eedb8000): Feb 6 10:45:01 [8323] INFO:core:sig_usr: signal 15 received Memory status (pkg): Feb 6 10:45:01 [8342] INFO:core:sig_usr: signal 15 received Memory status (pkg): Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 Feb 6 10:45:01 [8321] INFO:core:sig_usr: signal 15 received fm_status (0x7fb0eedb8000): Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 222952, used+overhead=286040, free=762536 max used (+overhead)= 291976 dumping free list: Feb 6 10:45:01 [8341] INFO:core:sig_usr: signal 15 received hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 2, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 2, unused: 0 bucket size: 24 - 24 (first 24) hash = 4 fragments no.: 1, unused: 0 bucket size: 32 - 32 (first 32) hash = 6 fragments no.: 4, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 14, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 5, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 11, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 2, unused: 0 bucket size: 80 - 80 (first 80) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) hash = 19 fragments no.: 3, unused: 0 bucket size: 152 - 152 (first 152) hash = 26 fragments no.: 1, unused: 0 bucket size: 208 - 208 (first 208) heap size= 1048576 Memory status (pkg): used= 222432, used+overhead=284288, free=764288 max used (+overhead)= 284296 dumping free list: heap size= 1048576 hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) used= 278824, used+overhead=340120, free=708456 max used (+overhead)= 340120 dumping free list: fm_status (0x7fb0eedb8000): hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 764584) TOTAL: 4 free fragments = 764608 free bytes ----------------------------- Feb 6 10:45:01 [8361] INFO:core:sig_usr: signal 15 received fm_status (0x7fb0eedb8000): heap size= 1048576 used= 222224, used+overhead=285120, free=763456 max used (+overhead)= 292624 dumping free list: hash = 1 fragments no.: 5, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 5, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 2, unused: 0 bucket size: 24 - 24 (first 24) hash = 4 fragments no.: 1, unused: 0 bucket size: 32 - 32 (first 32) hash = 6 fragments no.: 6, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 21, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 6, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 15, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 1, unused: 0 bucket size: 80 - 80 (first 80) hash = 11 fragments no.: 2, unused: 0 bucket size: 88 - 88 (first 88) hash = 12 fragments no.: 1, unused: 0 bucket size: 96 - 96 (first 96) hash = 19 fragments no.: 1, unused: 0 bucket size: 152 - 152 (first 152) hash = 30 fragments no.: 1, unused: 0 bucket size: 240 - 240 (first 240) hash = 47 fragments no.: 1, unused: 0 bucket size: 376 - 376 (first 376) hash = 52 fragments no.: 2, unused: 0 bucket size: 416 - 416 (first 416) hash = 128 fragments no.: 1, unused: 0 bucket size: 1024 - 1024 (first 1024) hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 756272) TOTAL: 73 free fragments = 763776 free bytes ----------------------------- used= 222432, used+overhead=284288, free=764288 heap size= 1048576 used= 222432, used+overhead=284288, free=764288 max used (+overhead)= 284296 dumping free list: hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 764584) TOTAL: 4 free fragments = 764608 free bytes ----------------------------- Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 222432, used+overhead=284288, free=764288 max used (+overhead)= 284288 dumping free list: hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 764584) TOTAL: 4 free fragments = 764608 free bytes ----------------------------- Feb 6 10:45:01 [8335] INFO:core:sig_usr: signal 15 received Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 222248, used+overhead=285000, free=763576 max used (+overhead)= 290712 dumping free list: hash = 1 fragments no.: 6, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 3, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 4, unused: 0 bucket size: 24 - 24 (first 24) hash = 6 fragments no.: 3, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 24, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 3, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 13, unused: 0 bucket size: 72 - 72 (first 72) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) hash = 19 fragments no.: 1, unused: 0 bucket size: 152 - 152 (first 152) hash = 26 fragments no.: 1, unused: 0 bucket size: 208 - 208 (first 208) hash = 30 fragments no.: 1, unused: 0 bucket size: 240 - 240 (first 240) hash = 52 fragments no.: 2, unused: 0 bucket size: 416 - 416 (first 416) hash = 70 fragments no.: 1, unused: 0 bucket size: 560 - 560 (first 560) hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 757480) TOTAL: 66 free fragments = 763896 free bytes ----------------------------- Feb 6 10:45:01 [8338] INFO:core:sig_usr: signal 15 received Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 222288, used+overhead=285040, free=763536 max used (+overhead)= 291504 dumping free list: hash = 1 fragments no.: 6, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 4, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 2, unused: 0 bucket size: 24 - 24 (first 24) hash = 6 fragments no.: 5, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 25, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 3, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 14, unused: 0 bucket size: 72 - 72 (first 72) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) hash = 30 fragments no.: 1, unused: 0 bucket size: 240 - 240 (first 240) hash = 52 fragments no.: 2, unused: 0 bucket size: 416 - 416 (first 416) hash = 113 fragments no.: 1, unused: 0 bucket size: 904 - 904 (first 904) hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 757392) TOTAL: 66 free fragments = 763856 free bytes ----------------------------- Feb 6 10:45:01 [8324] INFO:core:sig_usr: signal 15 received hash = 30 fragments no.: 1, unused: 0 bucket size: 240 - 240 (first 240) fm_status (0x7fb0eedb8000): hash = 52 fragments no.: 2, unused: 0 bucket size: 416 - 416 (first 416) heap size= 1048576 used= 227168, used+overhead=290064, free=758512 max used (+overhead)= 292560 dumping free list: hash = 1 fragments no.: 6, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 4, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 2, unused: 0 bucket size: 24 - 24 (first 24) hash = 4 fragments no.: 2, unused: 0 bucket size: 32 - 32 (first 32) hash = 6 fragments no.: 1, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 22, unused: 0 bucket size: 56 - 56 (first 56) hash = 9 fragments no.: 8, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 1, unused: 0 bucket size: 80 - 80 (first 80) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) hash = 12 fragments no.: 1, unused: 0 bucket size: 96 - 96 (first 96) hash = 19 fragments no.: 1, unused: 0 bucket size: 152 - 152 (first 152) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 756336) TOTAL: 50 free fragments = 758832 free bytes ----------------------------- hash = 1 fragments no.: 4, unused: 0 bucket size: 8 - 8 (first 8) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 708744) TOTAL: 5 free fragments = 708776 free bytes ----------------------------- Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 230888, used+overhead=292232, free=756344 max used (+overhead)= 284296 Memory status (pkg): dumping free list: heap size= 1048576 hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) used= 222208, used+overhead=285008, free=763568 hash = 70 fragments no.: 1, unused: 0 bucket size: 560 - 560 (first 560) fm_status (0x7fb0eedb8000): heap size= 1048576 hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 764584) max used (+overhead)= 292232 TOTAL: 4 free fragments = 764608 free bytes max used (+overhead)= 290696 dumping free list: hash = 1 fragments no.: 6, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 3, unused: 0 bucket size: 16 - 16 (first 16) hash = 3 fragments no.: 2, unused: 0 bucket size: 24 - 24 (first 24) hash = 4 fragments no.: 1, unused: 0 bucket size: 32 - 32 (first 32) hash = 6 fragments no.: 4, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 23, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 3, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 14, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 1, unused: 0 bucket size: 80 - 80 (first 80) hash = 11 fragments no.: 1, unused: 0 bucket size: 88 - 88 (first 88) 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 = 25 fragments no.: 1, unused: 0 bucket size: 200 - 200 (first 200) hash = 30 fragments no.: 1, unused: 0 bucket size: 240 - 240 (first 240) hash = 52 fragments no.: 3, unused: 0 bucket size: 416 - 416 (first 416) hash = 69 fragments no.: 1, unused: 0 bucket size: 552 - 552 (first 552) hash = 78 fragments no.: 1, unused: 0 bucket size: 624 - 624 (first 624) hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 756376) TOTAL: 69 free fragments = 763888 free bytes ----------------------------- used= 222288, used+overhead=284432, free=764144 max used (+overhead)= 289200 dumping free list: hash = 1 fragments no.: 3, unused: 0 bucket size: 8 - 8 (first 8) hash = 6 fragments no.: 4, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 1, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 4, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 8, unused: 0 bucket size: 72 - 72 (first 72) hash = 30 fragments no.: 3, unused: 0 bucket size: 240 - 240 (first 240) hash = 52 fragments no.: 1, unused: 0 bucket size: 416 - 416 (first 416) hash = 58 fragments no.: 1, unused: 0 bucket size: 464 - 464 (first 464) hash = 122 fragments no.: 1, unused: 0 bucket size: 976 - 976 (first 976) hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 759384) TOTAL: 28 free fragments = 764464 free bytes ----------------------------- hash = 175 fragments no.: 1, unused: 0 bucket size: 1400 - 1400 (first 1400) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 756560) TOTAL: 56 free fragments = 762856 free bytes ----------------------------- dumping free list: hash = 1 fragments no.: 4, unused: 0 bucket size: 8 - 8 (first 8) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 756632) TOTAL: 5 free fragments = 756664 free bytes ----------------------------- ----------------------------- Feb 6 10:45:01 [8293] DBG:core:pool_remove: connection still kept in the pool Feb 6 10:45:01 [8293] DBG:core:pool_remove: removing connection from the pool Feb 6 10:45:01 [8293] DBG:db_postgres:db_postgres_free_connection: PQfinish(0x7fb0eeee2720) Feb 6 10:45:01 [8293] DBG:db_postgres:db_postgres_free_connection: pkg_free(0x7fb0eedfb1a0) Feb 6 10:45:01 [8293] DBG:core:pool_remove: connection still kept in the pool Feb 6 10:45:01 [8293] DBG:core:pool_remove: connection still kept in the pool Feb 6 10:45:01 [8293] DBG:core:pool_remove: connection still kept in the pool Feb 6 10:45:01 [8293] DBG:xlog:destroy: destroy module... Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: tm_shutdown : start Feb 6 10:45:01 [8293] DBG:tm:unlink_timer_lists: emptying DELETE list Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: emptying hash table Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: releasing timers Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: removing semaphores Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: destroying callback lists Feb 6 10:45:01 [8293] DBG:tm:tm_shutdown: tm_shutdown : done Feb 6 10:45:01 [8293] DBG:core:pool_remove: removing connection from the pool Feb 6 10:45:01 [8293] DBG:db_postgres:db_postgres_free_connection: PQfinish(0x7fb0eeed9370) Feb 6 10:45:01 [8293] DBG:db_postgres:db_postgres_free_connection: pkg_free(0x7fb0eedfad48) Memory status (pkg): fm_status (0x7fb0eedb8000): heap size= 1048576 used= 202920, used+overhead=264520, free=784056 max used (+overhead)= 275504 dumping free list: hash = 1 fragments no.: 5, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 10, unused: 0 bucket size: 16 - 16 (first 16) hash = 4 fragments no.: 36, unused: 0 bucket size: 32 - 32 (first 32) hash = 6 fragments no.: 2, unused: 0 bucket size: 48 - 48 (first 48) hash = 9 fragments no.: 3, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 11, unused: 0 bucket size: 80 - 80 (first 80) hash = 14 fragments no.: 3, unused: 0 bucket size: 112 - 112 (first 112) hash = 16 fragments no.: 1, unused: 0 bucket size: 128 - 128 (first 128) hash = 1000 fragments no.: 1, unused: 0 bucket size: 8000 - 8000 (first 8000) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 773368) TOTAL: 73 free fragments = 784376 free bytes ----------------------------- Memory status (shm): fm_status (0x7fb0c98a3000): heap size= 536870912 used= 274600, used+overhead=311368, free=536559544 max used (+overhead)= 3105688 dumping free list: hash = 1 fragments no.: 56, unused: 0 bucket size: 8 - 8 (first 8) hash = 2 fragments no.: 9, 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.: 11, unused: 0 bucket size: 32 - 32 (first 32) hash = 5 fragments no.: 7, unused: 0 bucket size: 40 - 40 (first 40) hash = 6 fragments no.: 3, unused: 0 bucket size: 48 - 48 (first 48) hash = 7 fragments no.: 50, unused: 0 bucket size: 56 - 56 (first 56) hash = 8 fragments no.: 6, unused: 0 bucket size: 64 - 64 (first 64) hash = 9 fragments no.: 5, unused: 0 bucket size: 72 - 72 (first 72) hash = 10 fragments no.: 1, unused: 0 bucket size: 80 - 80 (first 80) hash = 11 fragments no.: 3, unused: 0 bucket size: 88 - 88 (first 88) hash = 13 fragments no.: 1, unused: 0 bucket size: 104 - 104 (first 104) hash = 15 fragments no.: 1, unused: 0 bucket size: 120 - 120 (first 120) hash = 19 fragments no.: 1, unused: 0 bucket size: 152 - 152 (first 152) hash = 21 fragments no.: 3, unused: 0 bucket size: 168 - 168 (first 168) hash = 45 fragments no.: 1, unused: 0 bucket size: 360 - 360 (first 360) hash = 69 fragments no.: 1, unused: 0 bucket size: 552 - 552 (first 552) hash = 71 fragments no.: 1, unused: 0 bucket size: 568 - 568 (first 568) hash = 78 fragments no.: 1, unused: 0 bucket size: 624 - 624 (first 624) hash = 91 fragments no.: 1, unused: 0 bucket size: 728 - 728 (first 728) hash = 112 fragments no.: 1, unused: 0 bucket size: 896 - 896 (first 896) hash = 128 fragments no.: 2, unused: 0 bucket size: 1024 - 1024 (first 1024) hash = 142 fragments no.: 1, unused: 0 bucket size: 1136 - 1136 (first 1136) hash = 151 fragments no.: 1, unused: 0 bucket size: 1208 - 1208 (first 1208) hash = 171 fragments no.: 1, unused: 0 bucket size: 1368 - 1368 (first 1368) hash = 224 fragments no.: 1, unused: 0 bucket size: 1792 - 1792 (first 1792) hash = 258 fragments no.: 2, unused: 0 bucket size: 2064 - 2064 (first 2064) hash = 263 fragments no.: 1, unused: 0 bucket size: 2104 - 2104 (first 2104) hash = 690 fragments no.: 1, unused: 0 bucket size: 5520 - 5520 (first 5520) hash = 811 fragments no.: 1, unused: 0 bucket size: 6488 - 6488 (first 6488) hash = 1026 fragments no.: 1, unused: 0 bucket size: 8208 - 8208 (first 8208) hash = 1563 fragments no.: 1, unused: 0 bucket size: 12504 - 12504 (first 12504) hash = 2049 fragments no.: 1, unused: 0 bucket size: 16384 - 32768 (first 20480) hash = 2051 fragments no.: 1, unused: 0 bucket size: 65536 - 131072 (first 98336) hash = 2056 fragments no.: 1, unused: 0 bucket size: 2097152 - 4194304 (first 2621440) hash = 2063 fragments no.: 1, unused: 0 bucket size: 268435456 - 536870912 (first 533762752) TOTAL: 187 free fragments = 536559544 free bytes ----------------------------- Feb 6 10:45:01 [8293] DBG:core:shm_mem_destroy: Feb 6 10:45:01 [8293] DBG:core:shm_mem_destroy: destroying the shared memory lock Feb 6 10:45:01 [8293] DBG:core:handle_sigs: terminating due to SIGCHLD