[OpenSER-Users] Openser problem in logs

Hi All When I start openser using /usr/local/sbin/openser it loads then I login using one user and I keep gettingthe logs below all the time is this normal Feb 1 14:03:54 [29077] DBG:core:parse_headers: flags=78 Feb 1 14:03:54 [29077] DBG:tm:t_lookup_request: start searching: hash=50458, isACK=0 Feb 1 14:03:54 [29077] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-5c484340d1308708-1--d87543- Feb 1 14:03:54 [29077] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Feb 1 14:03:54 [29077] DBG:tm:t_lookup_request: transaction found (T=0x4069bb80) Feb 1 14:03:54 [29077] DBG:tm:t_retransmit_reply: nothing to retransmit Feb 1 14:03:54 [29077] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 1 14:03:54 [29077] DBG:core:destroy_avp_list: destroying list (nil) Feb 1 14:03:54 [29077] DBG:core:receive_msg: cleaning up Feb 1 14:03:54 [29078] DBG:tm:utimer_routine: timer routine:7,tl=0x4069bccc next=(nil), timeout=12700000 Feb 1 14:03:54 [29078] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x4069bb80, SUBSCRIBE ... ) Feb 1 14:03:54 [29078] DBG:tm:set_timer: relative timeout is 4000000 Feb 1 14:03:54 [29078] DBG:tm:insert_timer_unsafe: [7]: 0x4069bccc (16700000) Feb 1 14:03:54 [29078] DBG:tm:retransmission_handler: retransmission_handler : done Feb 1 14:03:58 [29075] DBG:core:parse_msg: SIP Request: Feb 1 14:03:58 [29075] DBG:core:parse_msg: method: <SUBSCRIBE> Feb 1 14:03:58 [29075] DBG:core:parse_msg: uri: <sip:ali@jabber.splendor.net> Feb 1 14:03:58 [29075] DBG:core:parse_msg: version: <SIP/2.0> Feb 1 14:03:58 [29075] DBG:core:parse_headers: flags=2 Feb 1 14:03:58 [29075] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-5c484340d1308708-1--d87543->; state=6 Feb 1 14:03:58 [29075] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Feb 1 14:03:58 [29075] DBG:core:parse_via: end of header reached, state=5 Feb 1 14:03:58 [29075] DBG:core:parse_headers: via found, flags=2 Feb 1 14:03:58 [29075] DBG:core:parse_headers: this is the first via Feb 1 14:03:58 [29075] DBG:core:receive_msg: After parse_msg... Feb 1 14:03:58 [29075] DBG:core:receive_msg: preparing to run routing scripts... Feb 1 14:03:58 [29075] DBG:core:parse_headers: flags=100 Feb 1 14:03:58 [29075] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 1 14:03:58 [29075] DBG:core:parse_headers: flags=200 Feb 1 14:03:58 [29075] DBG:core:parse_to: end of header reached, state=10 Feb 1 14:03:58 [29075] DBG:core:parse_to: display={"ssafass"}, ruri={sip:ali@jabber.splendor.net} Feb 1 14:03:58 [29075] DBG:core:get_hdr_field: <To> [40]; uri=[sip:ali@jabber.splendor.net] Feb 1 14:03:58 [29075] DBG:core:get_hdr_field: to body ["ssafass"<sip:ali@jabber.splendor.net> ] Feb 1 14:03:58 [29075] DBG:core:get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE> Feb 1 14:03:58 [29075] DBG:core:get_hdr_field: content_length=0 Feb 1 14:03:58 [29075] DBG:core:get_hdr_field: found end of header Feb 1 14:03:58 [29075] DBG:rr:find_first_route: No Route headers found Feb 1 14:03:58 [29075] DBG:rr:loose_route: There is no Route HF Feb 1 14:03:58 [29075] DBG:core:grep_sock_info: checking if host==us: 19==15 && [jabber.splendor.net] == [193.227.186.153] Feb 1 14:03:58 [29075] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Feb 1 14:03:58 [29075] DBG:uri_db:does_uri_exist: User in request uri does exist Feb 1 14:03:58 [29075] DBG:core:db_free_rows: freeing 1 rows Feb 1 14:03:58 [29075] DBG:core:db_free_rows: row[0]=0x81841e0 Feb 1 14:03:58 [29075] DBG:core:db_free_rows: 0x81841e0=pkg_free() RES_ROWS Feb 1 14:03:58 [29075] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:ali@193.227.186.146:6242;rinstance=63a8660ec1b35169' Feb 1 14:03:58 [29075] DBG:tm:t_newtran: transaction on entrance=0xffffffff Feb 1 14:03:58 [29075] DBG:core:parse_headers: flags=ffffffffffffffff Feb 1 14:03:58 [29075] DBG:core:parse_headers: flags=78 Feb 1 14:03:58 [29075] DBG:tm:t_lookup_request: start searching: hash=50458, isACK=0 Feb 1 14:03:58 [29075] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-5c484340d1308708-1--d87543- Feb 1 14:03:58 [29075] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Feb 1 14:03:58 [29075] DBG:tm:t_lookup_request: transaction found (T=0x4069bb80) Feb 1 14:03:58 [29075] DBG:tm:t_retransmit_reply: nothing to retransmit Feb 1 14:03:58 [29075] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 1 14:03:58 [29075] DBG:core:destroy_avp_list: destroying list (nil) Feb 1 14:03:58 [29075] DBG:core:receive_msg: cleaning up Feb 1 14:03:58 [29078] DBG:tm:utimer_routine: timer routine:7,tl=0x4069bccc next=(nil), timeout=16700000 Feb 1 14:03:58 [29078] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x4069bb80, SUBSCRIBE ... ) Feb 1 14:03:58 [29078] DBG:tm:set_timer: relative timeout is 4000000 Feb 1 14:03:58 [29078] DBG:tm:insert_timer_unsafe: [7]: 0x4069bccc (20700000) Feb 1 14:03:58 [29078] DBG:tm:retransmission_handler: retransmission_handler : done Feb 1 14:04:02 [29077] DBG:core:parse_msg: SIP Request: Feb 1 14:04:02 [29077] DBG:core:parse_msg: method: <SUBSCRIBE> Feb 1 14:04:02 [29077] DBG:core:parse_msg: uri: <sip:ali@jabber.splendor.net> Feb 1 14:04:02 [29077] DBG:core:parse_msg: version: <SIP/2.0> Feb 1 14:04:02 [29077] DBG:core:parse_headers: flags=2 Feb 1 14:04:02 [29077] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-5c484340d1308708-1--d87543->; state=6 Feb 1 14:04:02 [29077] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Feb 1 14:04:02 [29077] DBG:core:parse_via: end of header reached, state=5 Feb 1 14:04:02 [29077] DBG:core:parse_headers: via found, flags=2 Feb 1 14:04:02 [29077] DBG:core:parse_headers: this is the first via Feb 1 14:04:02 [29077] DBG:core:receive_msg: After parse_msg... Feb 1 14:04:02 [29077] DBG:core:receive_msg: preparing to run routing scripts... Feb 1 14:04:02 [29077] DBG:core:parse_headers: flags=100 Feb 1 14:04:02 [29077] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 1 14:04:02 [29077] DBG:core:parse_headers: flags=200 Feb 1 14:04:02 [29077] DBG:core:parse_to: end of header reached, state=10 Feb 1 14:04:02 [29077] DBG:core:parse_to: display={"ssafass"}, ruri={sip:ali@jabber.splendor.net} Feb 1 14:04:02 [29077] DBG:core:get_hdr_field: <To> [40]; uri=[sip:ali@jabber.splendor.net] Feb 1 14:04:02 [29077] DBG:core:get_hdr_field: to body ["ssafass"<sip:ali@jabber.splendor.net> ] Feb 1 14:04:02 [29077] DBG:core:get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE> Feb 1 14:04:02 [29077] DBG:core:get_hdr_field: content_length=0 Feb 1 14:04:02 [29077] DBG:core:get_hdr_field: found end of header Feb 1 14:04:02 [29077] DBG:rr:find_first_route: No Route headers found Feb 1 14:04:02 [29077] DBG:rr:loose_route: There is no Route HF Feb 1 14:04:02 [29077] DBG:core:grep_sock_info: checking if host==us: 19==15 && [jabber.splendor.net] == [193.227.186.153] Feb 1 14:04:02 [29077] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Feb 1 14:04:02 [29077] DBG:uri_db:does_uri_exist: User in request uri does exist Feb 1 14:04:02 [29077] DBG:core:db_free_rows: freeing 1 rows Feb 1 14:04:02 [29077] DBG:core:db_free_rows: row[0]=0x817fca0 Feb 1 14:04:02 [29077] DBG:core:db_free_rows: 0x817fca0=pkg_free() RES_ROWS Feb 1 14:04:02 [29077] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:ali@193.227.186.146:6242;rinstance=63a8660ec1b35169' Feb 1 14:04:02 [29077] DBG:tm:t_newtran: transaction on entrance=0xffffffff Feb 1 14:04:02 [29077] DBG:core:parse_headers: flags=ffffffffffffffff Feb 1 14:04:02 [29077] DBG:core:parse_headers: flags=78 Feb 1 14:04:02 [29077] DBG:tm:t_lookup_request: start searching: hash=50458, isACK=0 Feb 1 14:04:02 [29077] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-5c484340d1308708-1--d87543- Feb 1 14:04:02 [29077] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Feb 1 14:04:02 [29077] DBG:tm:t_lookup_request: transaction found (T=0x4069bb80) Feb 1 14:04:02 [29077] DBG:tm:t_retransmit_reply: nothing to retransmit Feb 1 14:04:02 [29077] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 1 14:04:02 [29077] DBG:core:destroy_avp_list: destroying list (nil) Feb 1 14:04:02 [29077] DBG:core:receive_msg: cleaning up Feb 1 14:04:02 [29078] DBG:tm:utimer_routine: timer routine:7,tl=0x4069bccc next=(nil), timeout=20700000 Feb 1 14:04:02 [29078] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x4069bb80, SUBSCRIBE ... ) Feb 1 14:04:02 [29078] DBG:tm:set_timer: relative timeout is 4000000 Feb 1 14:04:02 [29078] DBG:tm:insert_timer_unsafe: [7]: 0x4069bccc (24700000) Feb 1 14:04:02 [29078] DBG:tm:retransmission_handler: retransmission_handler : done Feb 1 14:04:06 [29075] DBG:core:parse_msg: SIP Request: Feb 1 14:04:06 [29075] DBG:core:parse_msg: method: <SUBSCRIBE> Feb 1 14:04:06 [29075] DBG:core:parse_msg: uri: <sip:ali@jabber.splendor.net> Feb 1 14:04:06 [29075] DBG:core:parse_msg: version: <SIP/2.0> Feb 1 14:04:06 [29075] DBG:core:parse_headers: flags=2 Feb 1 14:04:06 [29075] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-5c484340d1308708-1--d87543->; state=6 Feb 1 14:04:06 [29075] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Feb 1 14:04:06 [29075] DBG:core:parse_via: end of header reached, state=5 Feb 1 14:04:06 [29075] DBG:core:parse_headers: via found, flags=2 Feb 1 14:04:06 [29075] DBG:core:parse_headers: this is the first via Feb 1 14:04:06 [29075] DBG:core:receive_msg: After parse_msg... Feb 1 14:04:06 [29075] DBG:core:receive_msg: preparing to run routing scripts... Feb 1 14:04:06 [29075] DBG:core:parse_headers: flags=100 Feb 1 14:04:06 [29075] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 1 14:04:06 [29075] DBG:core:parse_headers: flags=200 Feb 1 14:04:06 [29075] DBG:core:parse_to: end of header reached, state=10 Feb 1 14:04:06 [29075] DBG:core:parse_to: display={"ssafass"}, ruri={sip:ali@jabber.splendor.net} Feb 1 14:04:06 [29075] DBG:core:get_hdr_field: <To> [40]; uri=[sip:ali@jabber.splendor.net] Feb 1 14:04:06 [29075] DBG:core:get_hdr_field: to body ["ssafass"<sip:ali@jabber.splendor.net> ] Feb 1 14:04:06 [29075] DBG:core:get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE> Feb 1 14:04:06 [29075] DBG:core:get_hdr_field: content_length=0 Feb 1 14:04:06 [29075] DBG:core:get_hdr_field: found end of header Feb 1 14:04:06 [29075] DBG:rr:find_first_route: No Route headers found Feb 1 14:04:06 [29075] DBG:rr:loose_route: There is no Route HF Feb 1 14:04:06 [29075] DBG:core:grep_sock_info: checking if host==us: 19==15 && [jabber.splendor.net] == [193.227.186.153] Feb 1 14:04:06 [29075] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Feb 1 14:04:06 [29075] DBG:uri_db:does_uri_exist: User in request uri does exist Feb 1 14:04:06 [29075] DBG:core:db_free_rows: freeing 1 rows Feb 1 14:04:06 [29075] DBG:core:db_free_rows: row[0]=0x817fcc8 Feb 1 14:04:06 [29075] DBG:core:db_free_rows: 0x817fcc8=pkg_free() RES_ROWS Feb 1 14:04:06 [29075] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:ali@193.227.186.146:6242;rinstance=63a8660ec1b35169' Feb 1 14:04:06 [29075] DBG:tm:t_newtran: transaction on entrance=0xffffffff Feb 1 14:04:06 [29075] DBG:core:parse_headers: flags=ffffffffffffffff Feb 1 14:04:06 [29075] DBG:core:parse_headers: flags=78 Feb 1 14:04:06 [29075] DBG:tm:t_lookup_request: start searching: hash=50458, isACK=0 Feb 1 14:04:06 [29075] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-5c484340d1308708-1--d87543- Feb 1 14:04:06 [29075] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Feb 1 14:04:06 [29075] DBG:tm:t_lookup_request: transaction found (T=0x4069bb80) Feb 1 14:04:06 [29075] DBG:tm:t_retransmit_reply: nothing to retransmit Feb 1 14:04:06 [29075] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 1 14:04:06 [29075] DBG:core:destroy_avp_list: destroying list (nil) Feb 1 14:04:06 [29075] DBG:core:receive_msg: cleaning up Feb 1 14:04:06 [29078] DBG:tm:utimer_routine: timer routine:7,tl=0x4069bccc next=(nil), timeout=24700000 Feb 1 14:04:06 [29078] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x4069bb80, SUBSCRIBE ... ) Feb 1 14:04:06 [29078] DBG:tm:set_timer: relative timeout is 4000000 Feb 1 14:04:06 [29078] DBG:tm:insert_timer_unsafe: [7]: 0x4069bccc (28700000) Feb 1 14:04:06 [29078] DBG:tm:retransmission_handler: retransmission_handler : done Feb 1 14:04:10 [29077] DBG:core:parse_msg: SIP Request: Feb 1 14:04:10 [29077] DBG:core:parse_msg: method: <SUBSCRIBE> Feb 1 14:04:10 [29077] DBG:core:parse_msg: uri: <sip:ali@jabber.splendor.net> Feb 1 14:04:10 [29077] DBG:core:parse_msg: version: <SIP/2.0> Feb 1 14:04:10 [29077] DBG:core:parse_headers: flags=2 Feb 1 14:04:10 [29077] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d87543-5c484340d1308708-1--d87543->; state=6 Feb 1 14:04:10 [29077] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Feb 1 14:04:10 [29077] DBG:core:parse_via: end of header reached, state=5 Feb 1 14:04:10 [29077] DBG:core:parse_headers: via found, flags=2 Feb 1 14:04:10 [29077] DBG:core:parse_headers: this is the first via Feb 1 14:04:10 [29077] DBG:core:receive_msg: After parse_msg... Feb 1 14:04:10 [29077] DBG:core:receive_msg: preparing to run routing scripts... Feb 1 14:04:10 [29077] DBG:core:parse_headers: flags=100 Feb 1 14:04:10 [29077] DBG:maxfwd:is_maxfwd_present: value = 70 Feb 1 14:04:10 [29077] DBG:core:parse_headers: flags=200 Feb 1 14:04:10 [29077] DBG:core:parse_to: end of header reached, state=10 Feb 1 14:04:10 [29077] DBG:core:parse_to: display={"ssafass"}, ruri={sip:ali@jabber.splendor.net} Feb 1 14:04:10 [29077] DBG:core:get_hdr_field: <To> [40]; uri=[sip:ali@jabber.splendor.net] Feb 1 14:04:10 [29077] DBG:core:get_hdr_field: to body ["ssafass"<sip:ali@jabber.splendor.net> ] Feb 1 14:04:10 [29077] DBG:core:get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE> Feb 1 14:04:10 [29077] DBG:core:get_hdr_field: content_length=0 Feb 1 14:04:10 [29077] DBG:core:get_hdr_field: found end of header Feb 1 14:04:10 [29077] DBG:rr:find_first_route: No Route headers found Feb 1 14:04:10 [29077] DBG:rr:loose_route: There is no Route HF Feb 1 14:04:10 [29077] DBG:core:grep_sock_info: checking if host==us: 19==15 && [jabber.splendor.net] == [193.227.186.153] Feb 1 14:04:10 [29077] DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Feb 1 14:04:10 [29077] DBG:uri_db:does_uri_exist: User in request uri does exist Feb 1 14:04:10 [29077] DBG:core:db_free_rows: freeing 1 rows Feb 1 14:04:10 [29077] DBG:core:db_free_rows: row[0]=0x8179d78 Feb 1 14:04:10 [29077] DBG:core:db_free_rows: 0x8179d78=pkg_free() RES_ROWS Feb 1 14:04:10 [29077] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:ali@193.227.186.146:6242;rinstance=63a8660ec1b35169' Feb 1 14:04:10 [29077] DBG:tm:t_newtran: transaction on entrance=0xffffffff Feb 1 14:04:10 [29077] DBG:core:parse_headers: flags=ffffffffffffffff Feb 1 14:04:10 [29077] DBG:core:parse_headers: flags=78 Feb 1 14:04:10 [29077] DBG:tm:t_lookup_request: start searching: hash=50458, isACK=0 Feb 1 14:04:10 [29077] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d87543-5c484340d1308708-1--d87543- Feb 1 14:04:10 [29077] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Feb 1 14:04:10 [29077] DBG:tm:t_lookup_request: transaction found (T=0x4069bb80) Feb 1 14:04:10 [29077] DBG:tm:t_retransmit_reply: nothing to retransmit Feb 1 14:04:10 [29077] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Feb 1 14:04:10 [29077] DBG:core:destroy_avp_list: destroying list (nil) Feb 1 14:04:10 [29077] DBG:core:receive_msg: cleaning up Feb 1 14:04:10 [29078] DBG:tm:utimer_routine: timer routine:7,tl=0x4069bccc next=(nil), timeout=28700000 Feb 1 14:04:10 [29078] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x4069bb80, SUBSCRIBE ... ) Feb 1 14:04:10 [29078] DBG:tm:set_timer: relative timeout is 4000000 Feb 1 14:04:10 [29078] DBG:tm:insert_timer_unsafe: [7]: 0x4069bccc (32700000) Feb 1 14:04:10 [29078] DBG:tm:retransmission_handler: retransmission_handler : done Feb 1 14:04:11 [29075] DBG:core:udp_rcv_loop: probing packet received from 193.227.186.146 11518 Feb 1 14:04:12 [29078] DBG:tm:timer_routine: timer routine:0,tl=0x4069bce8 next=0x4069bdfc, timeout=31 Feb 1 14:04:12 [29078] DBG:tm:final_response_handler: stop retr. and send CANCEL (0x4069bb80) Feb 1 14:04:12 [29078] DBG:tm:t_should_relay_response: T_code=0, new_code=408 Feb 1 14:04:12 [29078] DBG:tm:t_pick_branch: picked branch 0, code 408 Feb 1 14:04:12 [29078] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=0 Feb 1 14:04:12 [29078] DBG:tm:t_should_relay_response: trying DNS-based failover Feb 1 14:04:12 [29078] DBG:tm:relay_reply: branch=0, save=0, relay=0 Feb 1 14:04:12 [29078] DBG:core:parse_headers: flags=ffffffffffffffff Feb 1 14:04:12 [29078] DBG:core:check_via_address: params 193.227.186.146, 192.168.0.176, 0 Feb 1 14:04:12 [29078] DBG:core:_shm_resize: resize(0) called Feb 1 14:04:12 [29078] DBG:tm:insert_timer_unsafe: [2]: 0x4069bbc8 (36) Feb 1 14:04:12 [29078] DBG:tm:relay_reply: sent buf=0x8179e70: SIP/2.0 4..., shmem=0x40699c70: SIP/2.0 4 Feb 1 14:04:12 [29078] DBG:tm:final_response_handler: done Feb 1 14:04:12 [29078] DBG:tm:timer_routine: timer routine:0,tl=0x4069bdfc next=(nil), timeout=31