[OpenSER-Users] openser 1.4 blocks

-----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@80.228.245.176:5050;lr> From: "HK SoftSwitch" <sip:v101@sip0.en.ewetel.de>;tag=7w4sllx8cc To: <sip:12345@sip0.en.ewetel.de;user=phone>;tag=0082-00000054-0103i0 Call-ID: 3c26c9bec396-loo61fn1yu42 CSeq: 3 BYE Max-Forwards: 70 Contact: <sip:v101@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@sip0.en.ewetel.de;user=phone} Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: <To> [74]; uri=[sip:044180002850@sip0.en.ewetel.de;user=phone] Jan 16 21:30:45 [8406] DBG:core:get_hdr_field: to body [<sip:044180002850@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@sip0.en.ewetel.de} MAIN : New Message <BYE> From: sip:v101@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@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@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