[OpenSER-Users] openser 1.4 blocks - CRITICAL?

Helmut Kuper helmut.kuper at ewetel.de
Thu Jan 17 11:18:08 CET 2008


-----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 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

_______________________________________________
Users mailing list
Users at lists.openser.org
http://lists.openser.org/cgi-bin/mailman/listinfo/users


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

iD8DBQFHjytg4tZeNddg3dwRAjgkAJ9p3w2jXhMpzyOEFA4Cx2AboHxYvgCfTLia
gQLRozPSPjybJktuI0G676Y=
=mktk
-----END PGP SIGNATURE-----




More information about the sr-users mailing list