[OpenSER-Users] openser 1.4 blocks

Helmut Kuper helmut.kuper at ewetel.de
Wed Jan 16 21:36:42 CET 2008 

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi,

when I send the following SIP-Message on my openser, openser blocks and
eats nearly all CPU power it can get:

BYE sip:80.228.245.138:5070 SIP/2.0
Via: SIP/2.0/UDP 212.6.95.88:1028;branch=z9hG4bK-7rhl6qnns4ej;rport
Route: <sip:212.6.123.118;lr=on;ftag=7w4sllx8cc>
Route:
<sip:212.6.123.118:5090;lr;ftag=7w4sllx8cc;vsf=ZlRqaD8wOzEbMTUlTiwzCnRNJ2F0eDBzMTZ0HVdlUg-->
Route: <sip:Gk-int at 80.228.245.176:5050;lr>
From: "HK SoftSwitch" <sip:v101 at sip0.en.ewetel.de>;tag=7w4sllx8cc
To: <sip:12345 at sip0.en.ewetel.de;user=phone>;tag=0082-00000054-0103i0
Call-ID: 3c26c9bec396-loo61fn1yu42
CSeq: 3 BYE
Max-Forwards: 70
Contact: <sip:v101 at 212.6.95.88:1028;line=nopsgn9d>;flow-id=1
User-Agent: snom370/7.1.30
RTP-RxStat:
Total_Rx_Pkts=120,Rx_Pkts=120,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0
RTP-TxStat: Total_Tx_Pkts=2263,Tx_Pkts=2263,Remote_Tx_Pkts=160
Content-Length: 0

What openser does is authentication, avp db loading an then a simple
t_relay().

opensers debuglog (level 8) is this:



Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:check_via_address: params 212.6.95.88,
212.6.95.88, 0
Jan 16 21:30:45 [8406] DBG:sl:run_sl_callbacks: callback id 0 entered
Jan 16 21:30:45 [8406] DBG:siptrace:trace_sl_onreply_out: trace off...
Jan 16 21:30:45 [8406] DBG:core:destroy_avp_list: destroying list 0xb5b00e50
Jan 16 21:30:45 [8406] DBG:core:receive_msg: cleaning up
Jan 16 21:30:45 [8406] DBG:core:parse_msg: SIP Request:
Jan 16 21:30:45 [8406] DBG:core:parse_msg:  method:  <BYE>
Jan 16 21:30:45 [8406] DBG:core:parse_msg:  uri:
<sip:80.228.245.138:5080>
Jan 16 21:30:45 [8406] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=2
Jan 16 21:30:45 [8406] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-goxekiv4ggfm>; state=6
Jan 16 21:30:45 [8406] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jan 16 21:30:45 [8406] DBG:core:parse_via: end of header reached, state=5
Jan 16 21:30:45 [8406] DBG:core:parse_headers: via found, flags=2
Jan 16 21:30:45 [8406] DBG:core:parse_headers: this is the first via
Jan 16 21:30:45 [8406] DBG:core:receive_msg: After parse_msg...
Jan 16 21:30:45 [8406] DBG:core:receive_msg: preparing to run routing
scripts...

BYE---------------------------------------------------------------------
[Wed Jan 16 21:30:45 2008] - NEW TRANSACTION!
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=78
Jan 16 21:30:45 [8406] DBG:core:parse_to_param: tag=0082-0000004f-00e7i0
Jan 16 21:30:45 [8406] DBG:core:parse_to: end of header reached, state=29
Jan 16 21:30:45 [8406] DBG:core:parse_to: display={},
ruri={sip:044180002850 at sip0.en.ewetel.de;user=phone}
Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: <To> [74];
uri=[sip:044180002850 at sip0.en.ewetel.de;user=phone]
Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: to body
[<sip:044180002850 at sip0.en.ewetel.de;user=phone>]
Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: cseq <CSeq>: <4> <BYE>
Jan 16 21:30:45 [8406] DBG:tm:t_lookup_request: start searching:
hash=36300, isACK=0
Jan 16 21:30:45 [8406] DBG:tm:matching_3261: RFC3261 transaction
matching failed
Jan 16 21:30:45 [8406] DBG:tm:t_lookup_request: no transaction found
Jan 16 21:30:45 [8406] DBG:core:parse_to_param: tag=bpl4kg8f57
Jan 16 21:30:45 [8406] DBG:core:parse_to: end of header reached, state=29
Jan 16 21:30:45 [8406] DBG:core:parse_to: display={"HK SoftSwitch"},
ruri={sip:v101 at sip0.en.ewetel.de}
MAIN    : New Message <BYE>  From: sip:v101 at sip0.en.ewetel.de, To:
sip:80.228.245.138:5080
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=100
Jan 16 21:30:45 [8406] DBG:maxfwd:is_maxfwd_present: value = 70
Route 22: Check type of source ... Jan 16 21:30:45 [8406]
DBG:permissions:allow_source_address: looking for <1, 585f06d4, 1028>
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=800000000
Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: content_length=0
Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: found end of header
Jan 16 21:30:45 [8406] DBG:core:pv_get_ppi_attr: no P-Preferred-Identity
header
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
17==13 &&  [sip0.en.ewetel.de] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
17==13 &&  [sip0.en.ewetel.de] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jan 16 21:30:45 [8406] DBG:avpops:ops_dbquery_avps: query [SELECT
uri_user FROM uri WHERE username='v101' AND domain='sip0.en.ewetel.de'
LIMIT 1]
Jan 16 21:30:45 [8406] DBG:avpops:db_query_avp: rows [1]
Jan 16 21:30:45 [8406] DBG:avpops:db_query_avp: row [0]
Jan 16 21:30:45 [8406] DBG:avpops:db_close_query: close avp query
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: freeing 1 rows
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[0]=0x81dde58
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: 0x81dde58=pkg_free() RES_ROWS
From-URI belongs to xxxxxxxxxxx
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:auth:check_nonce: comparing
[478e6aa112f6919eb75ced3104f1774c59a1ce01] and
[478e6aa112f6919eb75ced3104f1774c59a1ce01]
Jan 16 21:30:45 [8406] DBG:auth_db:get_ha1: HA1 string calculated:
98eb7bda25d62322c1ff8261c216e8ad
Jan 16 21:30:45 [8406] DBG:auth:check_response: our result =
'43c9a3529f44aa0e6dda2f6f0894632c'
Jan 16 21:30:45 [8406] DBG:auth:check_response: authorization is OK
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: freeing 1 rows
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[0]=0x81dde88
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: 0x81dde88=pkg_free() RES_ROWS
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Jan 16 21:30:45 [8406] DBG:core:comp_scriptvar: str 29 : xxxxxxxxx
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Route 04: <BYE>-Authentication OK

Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=14000
Route 07: <BYE>: Loading A-Profile ... Jan 16 21:30:45 [8406]
DBG:avpops:dbrow2avp: db_flags=0, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=0, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=0, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=0, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=2, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:dbrow2avp: db_flags=0, flags=3
Jan 16 21:30:45 [8406] DBG:avpops:db_close_query: close avp query
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: freeing 15 rows
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[0]=0x81de068
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[1]=0x81de070
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[2]=0x81de078
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[3]=0x81de080
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[4]=0x81de088
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[5]=0x81de090
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[6]=0x81de098
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[7]=0x81de0a0
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[8]=0x81de0a8
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[9]=0x81de0b0
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[10]=0x81de0b8
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[11]=0x81de0c0
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[12]=0x81de0c8
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[13]=0x81de0d0
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: row[14]=0x81de0d8
Jan 16 21:30:45 [8406] DBG:core:db_free_rows: 0x81de068=pkg_free() RES_ROWS
Jan 16 21:30:45 [8406] DBG:avpops:ops_dbload_avps: loaded avps = 15
OK
Jan 16 21:30:45 [8406] DBG:core:comp_scriptvar: int 20 : 1 / 1
MAIN    : <BYE>: From-Data is: User='v101', Domain='sip0.en.ewetel.de',
URI='sip:v101 at sip0.en.ewetel.de'
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=200
Jan 16 21:30:45 [8406] DBG:rr:is_preloaded: is_preloaded: No
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5080
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5080
Jan 16 21:30:45 [8406] DBG:core:check_self: host != me
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [212.6.123.118] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jan 16 21:30:45 [8406] DBG:rr:after_loose: Topmost route URI:
'sip:212.6.123.118;lr=on;ftag=bpl4kg8f57' is me
Jan 16 21:30:45 [8406] DBG:rr:after_loose: URI to be processed:
'sip:212.6.123.118:5090;lr;ftag=bpl4kg8f57;vsf=ZlRqaD8wOzEbMTUlTiwzCnRNJ2F0eDBzMTZ0HVdlUg--'
Jan 16 21:30:45 [8406] DBG:rr:after_loose: Next URI is a loose router
Jan 16 21:30:45 [8406] DBG:rr:run_rr_callbacks: callback id 0 entered
with <lr=on;ftag=bpl4kg8f57>
DEBUG:uac:restore_from: getting 'vsf' Route param
DEBUG:uac:restore_from: Route param 'vsf' not found
Jan 16 21:30:45 [8406] DBG:avpops:ops_check_avp: check <17> against <8>
as int /256
Jan 16 21:30:45 [8406] DBG:avpops:ops_check_avp: no match
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=200
Jan 16 21:30:45 [8406] DBG:rr:is_preloaded: is_preloaded: No
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5080
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5080
Jan 16 21:30:45 [8406] DBG:core:check_self: host != me
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [212.6.123.118] == [212.6.123.118]
Jan 16 21:30:45 [8406] DBG:core:grep_sock_info: checking if port 5060
matches port 5060
Jan 16 21:30:45 [8406] DBG:rr:after_loose: Topmost route URI:
'sip:212.6.123.118;lr=on;ftag=bpl4kg8f57' is me
Jan 16 21:30:45 [8406] DBG:rr:after_loose: URI to be processed:
'sip:212.6.123.118:5090;lr;ftag=bpl4kg8f57;vsf=ZlRqaD8wOzEbMTUlTiwzCnRNJ2F0eDBzMTZ0HVdlUg--'
Jan 16 21:30:45 [8406] DBG:rr:after_loose: Next URI is a loose router
Jan 16 21:30:45 [8406] DBG:rr:run_rr_callbacks: callback id 0 entered
with <lr=on;ftag=bpl4kg8f57>
DEBUG:uac:restore_from: getting 'vsf' Route param
DEBUG:uac:restore_from: Route param 'vsf' not found
MAIN    : Loose-Route
Jan 16 21:30:45 [8406] DBG:uri:has_totag: totag found
Route 08: <BYE>: Set Accounting for this call!
Route 11: Removing secret Headers
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:registrar:lookup: '80.228.245.138' Not found
in usrloc
Route 01: Relaying BYE: RURI=sip:80.228.245.138:5080
F=sip:v101 at sip0.en.ewetel.de IP=212.6.95.88; Calltimeout=<null>
[Wed Jan 16 21:30:45 2008]
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Route 01: Next Hop DST-Set
Jan 16 21:30:45 [8406] DBG:tm:t_newtran: transaction on entrance=(nil)
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=78
Jan 16 21:30:45 [8406] DBG:tm:t_lookup_request: start searching:
hash=36300, isACK=0
Jan 16 21:30:45 [8406] DBG:tm:matching_3261: RFC3261 transaction
matching failed
Jan 16 21:30:45 [8406] DBG:tm:t_lookup_request: no transaction found
Jan 16 21:30:45 [8406] DBG:tm:run_reqin_callbacks: trans=0xb5b01048,
callback type 1, id 1 entered
Jan 16 21:30:45 [8406] DBG:siptrace:trace_onreq_in: trace off...
Jan 16 21:30:45 [8406] DBG:tm:run_reqin_callbacks: trans=0xb5b01048,
callback type 1, id 0 entered
Jan 16 21:30:45 [8406] DBG:core:parse_headers: flags=78



Any ideas, why it hangs eating all my cpu power ?

regards
Helmut
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.5 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFHjmra4tZeNddg3dwRAvu4AJ4rK5jCbKF9UDGu8FP1suEyRHkwigCeM58p
K5a16nleRI+zZujWTI0Ntfs=
=XJqP
-----END PGP SIGNATURE-----

More information about the Users mailing list