-----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
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hello,
Update:
I reduced my openser.cfg until the faulty configuration was identified:
# # $Id: openser.cfg,v 1.6.2.1 2006/07/17 15:51:03 klaus_darilion Exp $ # # simple quick-start config script #
# ----------- global configuration parameters ------------------------
debug=4 # debug level (cmd line: -dddddddddd) fork=no log_stderror=1 # (cmd line: -E)
check_via=yes # (cmd. line: -v) dns=no # (cmd. line: -r) rev_dns=no # (cmd. line: -R) listen=212.6.123.118 port=5060 children=1
user="ruth" group="voip"
# ------------------ module loading ---------------------------------- mpath="/home/hk/openser/lib/openser/modules/"
# Uncomment this if you want to use SQL database loadmodule "tm.so" loadmodule "sl.so" loadmodule "rr.so" loadmodule "uri.so" # ----------------- AVP aliase (zum einfacheren Lesen) ---------------
# ------------------------- request routing logic -------------------
# main routing logic
route{ ~ #has_totag(); ~ if(loose_route()) {t_relay();} ~ else sl_send_reply("404", "eee"); }
send the SIP message from below to an openser running in debugmode and without forking u will c openser never comes back from t_relay.
Uncomment has_totag() line and everything is ok.
Obviuosly has_totag() does more than "Check if To header field uri contains tag parameter. " as uri module doc say.
regards Helmut
Helmut Kuper schrieb: | 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
_______________________________________________ Users mailing list Users@lists.openser.org http://lists.openser.org/cgi-bin/mailman/listinfo/users
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hi again,
forget my last mail. ha_totag() works as normal.
To hang openser just put the mentioned message into t_relay():
route{ t_relay(); }
Dunno whether this behaviour is normal or not, but I expected that t_relay() returns an error.
regards helmut
Hi Helmut,
After blocking, have you inspect with gdb the hung process? try to get a backtrace.
regards, Bogdan
Helmut Kuper wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hi again,
forget my last mail. ha_totag() works as normal.
To hang openser just put the mentioned message into t_relay():
route{ t_relay(); }
Dunno whether this behaviour is normal or not, but I expected that t_relay() returns an error.
regards helmut -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.5 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org
iD8DBQFHjy2T4tZeNddg3dwRArSdAJ9C1tj/3sy6o4EjAR/ygT204IThZACgtycZ J2e4SthVgWjx5lRmeuZ/3KI= =vJwj -----END PGP SIGNATURE-----
Users mailing list Users@lists.openser.org http://lists.openser.org/cgi-bin/mailman/listinfo/users
-
Bogdan-Andrei Iancu -
Helmut Kuper