[OpenSER-Users] Openser problem in logs

Ali Jawad ali.jawad at splendor.net
Fri Feb 1 13:04:56 CET 2008 

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 at 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 at jabber.splendor.net}

Feb  1 14:03:58 [29075] DBG:core:get_hdr_field: <To> [40];
uri=[sip:ali at jabber.splendor.net]

Feb  1 14:03:58 [29075] DBG:core:get_hdr_field: to body
["ssafass"<sip:ali at 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 at 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 at 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 at jabber.splendor.net}

Feb  1 14:04:02 [29077] DBG:core:get_hdr_field: <To> [40];
uri=[sip:ali at jabber.splendor.net]

Feb  1 14:04:02 [29077] DBG:core:get_hdr_field: to body
["ssafass"<sip:ali at 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 at 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 at 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 at jabber.splendor.net}

Feb  1 14:04:06 [29075] DBG:core:get_hdr_field: <To> [40];
uri=[sip:ali at jabber.splendor.net]

Feb  1 14:04:06 [29075] DBG:core:get_hdr_field: to body
["ssafass"<sip:ali at 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 at 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 at 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 at jabber.splendor.net}

Feb  1 14:04:10 [29077] DBG:core:get_hdr_field: <To> [40];
uri=[sip:ali at jabber.splendor.net]

Feb  1 14:04:10 [29077] DBG:core:get_hdr_field: to body
["ssafass"<sip:ali at 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 at 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

 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kamailio.org/pipermail/users/attachments/20080201/a024d4fb/attachment.htm

More information about the Users mailing list