[OpenSER-Devel] [ openser-Bugs-1876311 ] OpenSER Message of Death?

SourceForge.net noreply at sourceforge.net
Tue Jan 22 08:37:00 UTC 2008


Bugs item #1876311, was opened at 2008-01-21 01:03
Message generated for change (Comment added) made by nobody
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1876311&group_id=139143

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: ver devel
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Helmut Kuper (hekuper)
Assigned to: Bogdan-Andrei Iancu (bogdan_iancu)
Summary: OpenSER Message of Death?

Initial Comment:
I found that when u send this SIP-Message:

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


to an openser with this config:

#
# $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{
~                t_relay();
}



openser will stop working, consuming all CPU-Power.


regards
Helmut


----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-22 00:37

Message:
Logged In: NO 

Hi Dan,

yes, I have that line in my sip_msg.c



----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-21 23:53

Message:
Logged In: NO 

The bug that caused openser to sometimes enter an endless loop was caused
by not having the sibling header in the clone set to NULL prior to being
replicated. This was fixed in r3433. You sould check that in
modules/tm/sip_msg.c you have line 525 that reads

new_msg->sibling=0;

If you have it then this is probably another issue, else your copy may
have not updated this particular file.

Dan


----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-21 10:09

Message:
Logged In: NO 

Hello Bogdan,

I use for testing build 3557

ruth at vm-en-test0:~/x/tmp$ sbin/openser -V
version: openser 1.4.0dev0-notls (i386/linux)
flags: STATS: Off, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST, SHM_MEM,
SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
svnrevision: 2:3557
@(#) $Id: main.c 3552 2008-01-20 17:46:48Z bogdan_iancu $
main.c compiled on 15:28:02 Jan 21 2008 with gcc 4.0.3



----------------------------------------------------------------------

Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2008-01-21 09:41

Message:
Logged In: YES 
user_id=1275325
Originator: NO

The LINK_SIBLING_HEADER macro is present only in the devel version and
there was an inital bug related to it, bug fixed (hopefully) some time
ago.

Are you sure you are using the latest SVN trunk version?

Regards,
Bogdan

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-21 09:20

Message:
Logged In: NO 

I did a BT to a wild process:

ruth at vm-en-test0:~/tmp$ gdb openser 18445
GNU gdb 6.4-debian
Copyright 2005 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you
are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for
details.
This GDB was configured as "i486-linux-gnu"...openser: No such file or
directory.

Attaching to process 18445
Reading symbols from /home/hk/openser/sbin/openser...done.
Using host libthread_db library "/lib/tls/i686/cmov/libthread_db.so.1".
Reading symbols from /lib/tls/i686/cmov/libdl.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libdl.so.2
Reading symbols from /lib/tls/i686/cmov/libresolv.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libresolv.so.2
Reading symbols from /lib/tls/i686/cmov/libc.so.6...done.
Loaded symbols for /lib/tls/i686/cmov/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /home/hk/openser/lib/openser/modules/tm.so...done.
Loaded symbols for /home/hk/openser/lib/openser/modules/tm.so
Reading symbols from /home/hk/openser/lib/openser/modules/sl.so...done.
Loaded symbols for /home/hk/openser/lib/openser/modules/sl.so
Reading symbols from /home/hk/openser/lib/openser/modules/rr.so...done.
Loaded symbols for /home/hk/openser/lib/openser/modules/rr.so
Reading symbols from /home/hk/openser/lib/openser/modules/uri.so...done.
Loaded symbols for /home/hk/openser/lib/openser/modules/uri.so
Reading symbols from /home/hk/openser/lib/openser/modules/xlog.so...done.
Loaded symbols for /home/hk/openser/lib/openser/modules/xlog.so
Reading symbols from /lib/tls/i686/cmov/libnss_compat.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libnss_compat.so.2
Reading symbols from /lib/tls/i686/cmov/libnsl.so.1...done.
Loaded symbols for /lib/tls/i686/cmov/libnsl.so.1
Reading symbols from /lib/tls/i686/cmov/libnss_nis.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libnss_nis.so.2
Reading symbols from /lib/tls/i686/cmov/libnss_files.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libnss_files.so.2
Reading symbols from /lib/tls/i686/cmov/libnss_dns.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libnss_dns.so.2
sip_msg_cloner (org_msg=0x817d618, sip_msg_len=0xbfce55c8) at
sip_msg.c:648
648                                             LINK_SIBLING_HEADER(route,
new_hdr);
(gdb) bt
#0  sip_msg_cloner (org_msg=0x817d618, sip_msg_len=0xbfce55c8) at
sip_msg.c:648
#1  0xb7e32ff3 in build_cell (p_msg=0x817d618) at h_table.c:288
#2  0xb7e4bcef in t_newtran (p_msg=0x817d618) at t_lookup.c:1000
#3  0xb7e40e0c in t_relay_to (p_msg=0x817d618, proxy=0x0, flags=0) at
t_funcs.c:200
#4  0xb7e5f28b in w_t_relay (p_msg=0x817d618, proxy=0x0, flags=0x0) at
tm.c:929
#5  0x08052491 in do_action (a=0x817c8d0, msg=0x817d618) at action.c:816
#6  0x08054d27 in run_action_list (a=0x817c8d0, msg=0x817d618) at
action.c:132
#7  0x0805511f in run_top_route (a=0x817c8d0, msg=0x817be38) at
action.c:112
#8  0x08093d2b in receive_msg (
    buf=0x8167180 "BYE sip:80.228.245.138:5070 SIP/2.0\r\nVia: SIP/2.0/UDP
192.168.9.36:51660;branch=z9hG4bK.2b98d0e0;rport;alias\r\nVia: SIP/2.0/UDP
212.6.95.88:1028;branch=z9hG4bK-7rhl6qnns4ej;rport\r\nRoute:
<sip:212.6.123"..., len=836, rcv_info=0xbfce5cd4) at receive.c:156
#9  0x080d2f6d in udp_rcv_loop () at udp_server.c:438
#10 0x0806c62b in main (argc=3, argv=0xbfce5ec4) at main.c:747
(gdb)

Helmut




----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-21 08:55

Message:
Logged In: NO 

If strace and ltrace show nothing it most likely it's in an infinite loop
from where it calls no library or system functions. You can attach with gdb
and get a backtrace that would indicate where inside the code it is
looping.

Dan


----------------------------------------------------------------------

Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2008-01-21 08:37

Message:
Logged In: YES 
user_id=1275325
Originator: NO

Hi Helmut,

Try to attach with gdb to the "wild" process and get a backtrace (bt) -
this will give a clue where to look.

Thanks,
Bogdan

----------------------------------------------------------------------

Comment By: Helmut Kuper (hekuper)
Date: 2008-01-21 08:22

Message:
Logged In: YES 
user_id=1851349
Originator: YES

Hi Dan,

well, the different PIDs are caused by different test runs. Sorry for
that.

So here a correct log:

openser log:

Jan 21 17:13:06 [16946] DBG:core:parse_msg: SIP Request:
Jan 21 17:13:06 [16946] DBG:core:parse_msg:  method:  <BYE>
Jan 21 17:13:06 [16946] DBG:core:parse_msg:  uri:    
<sip:80.228.245.138:5070>
Jan 21 17:13:06 [16946] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 21 17:13:06 [16946] DBG:core:parse_headers: flags=2
Jan 21 17:13:07 [16946] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK.19249b4c>; state=6
Jan 21 17:13:07 [16946] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=6
Jan 21 17:13:07 [16946] DBG:core:parse_via_param: found param type 237,
<alias> = <n/a>; state=16
Jan 21 17:13:07 [16946] DBG:core:parse_via: end of header reached,
state=5
Jan 21 17:13:07 [16946] DBG:core:parse_headers: via found, flags=2
Jan 21 17:13:07 [16946] DBG:core:parse_headers: this is the first via
Jan 21 17:13:07 [16946] DBG:core:receive_msg: After parse_msg...
Jan 21 17:13:07 [16946] DBG:core:receive_msg: preparing to run routing
scripts...
Jan 21 17:13:07 [16946] DBG:tm:t_newtran: transaction on
entrance=0xffffffff
Jan 21 17:13:07 [16946] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 21 17:13:07 [16946] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-7rhl6qnns4ej>; state=6
Jan 21 17:13:07 [16946] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jan 21 17:13:07 [16946] DBG:core:parse_via: end of header reached,
state=5
Jan 21 17:13:07 [16946] DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Jan 21 17:13:07 [16946] DBG:core:parse_headers: parse_headers: this is the
second via
Jan 21 17:13:07 [16946] DBG:core:parse_to_param: tag=0082-00000054-0103i0
Jan 21 17:13:07 [16946] DBG:core:parse_to: end of header reached,
state=29
Jan 21 17:13:07 [16946] DBG:core:parse_to: display={},
ruri={sip:12345 at sip0.en.ewetel.de;user=phone}
Jan 21 17:13:07 [16946] DBG:core:get_hdr_field: <To> [67];
uri=[sip:12345 at sip0.en.ewetel.de;user=phone]
Jan 21 17:13:07 [16946] DBG:core:get_hdr_field: to body
[<sip:12345 at sip0.en.ewetel.de;user=phone>]
Jan 21 17:13:07 [16946] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Jan 21 17:13:07 [16946] DBG:core:get_hdr_field: content_length=0
Jan 21 17:13:07 [16946] DBG:core:get_hdr_field: found end of header
Jan 21 17:13:07 [16946] DBG:core:parse_headers: flags=78
Jan 21 17:13:07 [16946] DBG:tm:t_lookup_request: start searching:
hash=19447, isACK=0
Jan 21 17:13:07 [16946] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jan 21 17:13:07 [16946] DBG:tm:t_lookup_request: no transaction found



top:
top - 17:17:52 up 57 days, 17:58,  3 users,  load average: 1.02, 0.66,
0.28
Tasks:  90 total,   3 running,  87 sleeping,   0 stopped,   0 zombie
Cpu(s): 100.0% us,  0.0% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0%
si
Mem:    775576k total,   743652k used,    31924k free,    50732k buffers
Swap:  1542200k total,      124k used,  1542076k free,   478800k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
16946 ruth      25   0 37324 3224 3004 R 99.7  0.4   4:42.58 openser
    1 root      16   0  1568  532  460 S  0.0  0.1   0:06.75 init
    2 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 migration/0
    3 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/0

ltrace -p 16946 show nothing




----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-21 08:08

Message:
Logged In: NO 

The process that consumes 100% CPU and the one that have processed the BYE
message are not the same (look at the PIDs). You should check what is the
role of the process that consumes 100% CPU using openserctl ps. Then you
could see what it's actually doing using strace, ltrace and gdb.

Dan


----------------------------------------------------------------------

Comment By: Henning Westerholt (henningw)
Date: 2008-01-21 07:22

Message:
Logged In: YES 
user_id=337916
Originator: NO

Hm, strange. I would like to get a more detailed cause for this error than
'kernel problem'. Have you tried to analyze a core dump from the process
hanging in the loop? Perhaps this gives some more hints about the
problem..



----------------------------------------------------------------------

Comment By: Helmut Kuper (hekuper)
Date: 2008-01-21 07:10

Message:
Logged In: YES 
user_id=1851349
Originator: YES

No, there is no SIP-Traffic. Messages comes into openser an nothing comes
out.

I installed latest openser on ubuntu 2.6.20-15-server (feisty) with test
config and test message (see below). I replaced all sip0.en. ... as well as
IP-Adresses of my old server with new server's address and the error
disappeard. Obviously ubuntu 2.6.15-29-server (dapper) is not a good choice
for openser ...

grrr have to update my machines now ... or do u think we should run for
that error ?

Thanks for ur help so far.


----------------------------------------------------------------------

Comment By: Henning Westerholt (henningw)
Date: 2008-01-21 07:02

Message:
Logged In: YES 
user_id=337916
Originator: NO

I use (k)ubuntu 7.10, kernel 2.6.22-14. My environment is not identical to
your test setup, because of the network setup, perhaps this prevent the
triggering of this bug on my machine.

The periodical select is produced from the TCP receiver process and is not
problematical. Did you send the SIP msg over TCP or UDP? 

In the log it seems that another message is parsed before the msg you've
attached to this bug (branch z9hG4bK.7b5f690b). Where does this BYE came
from? Any signs of this loop you've mentioned above in the log files?

Cheers,

Henning

----------------------------------------------------------------------

Comment By: Helmut Kuper (hekuper)
Date: 2008-01-21 06:33

Message:
Logged In: YES 
user_id=1851349
Originator: YES

Hi Henning,

what kind of OS do u use ? I use ubuntu 2.6.15-29-server. Meybe there is a
bug in my OS ...  

----------------------------------------------------------------------

Comment By: Helmut Kuper (hekuper)
Date: 2008-01-21 05:59

Message:
Logged In: YES 
user_id=1851349
Originator: YES

Hi again,

I compiled openser trunk (build 3557) and tested it. Same result. Openser
hangs somwhere in a loop or so.

A strace as a wrapper around openser in no fork mode dbug level 4 says
this:

[pid  2829] time([1200923769])          = 1200923769
[pid  2829] write(2, "Jan 21 14:56:09 [2829] DBG:core:"..., 56Jan 21
14:56:09 [2829] DBG:core:parse_headers: flags=78
) = 56
[pid  2829] time([1200923769])          = 1200923769
[pid  2829] write(2, "Jan 21 14:56:09 [2829] DBG:tm:t_"..., 85Jan 21
14:56:09 [2829] DBG:tm:t_lookup_request: start searching: hash=19447,
isACK=0
) = 85
[pid  2829] time([1200923769])          = 1200923769
[pid  2829] write(2, "Jan 21 14:56:09 [2829] DBG:tm:ma"..., 81Jan 21
14:56:09 [2829] DBG:tm:matching_3261: RFC3261 transaction matching failed
) = 81
[pid  2829] time([1200923769])          = 1200923769
[pid  2829] write(2, "Jan 21 14:56:09 [2829] DBG:tm:t_"..., 69Jan 21
14:56:09 [2829] DBG:tm:t_lookup_request: no transaction found
) = 69
[pid  2830] <... select resumed> )      = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
[pid  2830] select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)

the "select" line comes priodically (2-3 times per sec)



----------------------------------------------------------------------

Comment By: Helmut Kuper (hekuper)
Date: 2008-01-21 05:45

Message:
Logged In: YES 
user_id=1851349
Originator: YES

Hi Henning,

I got this log from openser:

Jan 21 14:36:40 [27027] DBG:core:parse_msg: SIP Request:
Jan 21 14:36:40 [27027] DBG:core:parse_msg:  method:  <BYE>
Jan 21 14:36:40 [27027] DBG:core:parse_msg:  uri:    
<sip:80.228.245.138:5070>
Jan 21 14:36:40 [27027] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 21 14:36:40 [27027] DBG:core:parse_headers: flags=2
Jan 21 14:36:40 [27027] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK.7b5f690b>; state=6
Jan 21 14:36:40 [27027] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=6
Jan 21 14:36:40 [27027] DBG:core:parse_via_param: found param type 237,
<alias> = <n/a>; state=16
Jan 21 14:36:40 [27027] DBG:core:parse_via: end of header reached,
state=5
Jan 21 14:36:40 [27027] DBG:core:parse_headers: via found, flags=2
Jan 21 14:36:40 [27027] DBG:core:parse_headers: this is the first via
Jan 21 14:36:40 [27027] DBG:core:receive_msg: After parse_msg...
Jan 21 14:36:40 [27027] DBG:core:receive_msg: preparing to run routing
scripts...
Jan 21 14:36:40 [27027] DBG:core:parse_headers: flags=78
Jan 21 14:36:40 [27027] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-7rhl6qnns4ej>; state=6
Jan 21 14:36:40 [27027] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jan 21 14:36:40 [27027] DBG:core:parse_via: end of header reached,
state=5
Jan 21 14:36:40 [27027] DBG:core:parse_headers: via found, flags=78
Jan 21 14:36:40 [27027] DBG:core:parse_headers: parse_headers: this is the
second via
Jan 21 14:36:40 [27027] DBG:core:parse_to_param: tag=0082-00000054-0103i0
Jan 21 14:36:40 [27027] DBG:core:parse_to: end of header reached,
state=29
Jan 21 14:36:40 [27027] DBG:core:parse_to: display={},
ruri={sip:12345 at sip0.en.ewetel.de;user=phone}
Jan 21 14:36:40 [27027] DBG:core:get_hdr_field: <To> [67];
uri=[sip:12345 at sip0.en.ewetel.de;user=phone]
Jan 21 14:36:40 [27027] DBG:core:get_hdr_field: to body
[<sip:12345 at sip0.en.ewetel.de;user=phone>]
Jan 21 14:36:40 [27027] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Jan 21 14:36:40 [27027] DBG:tm:t_lookup_request: start searching:
hash=19447, isACK=0
Jan 21 14:36:40 [27027] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jan 21 14:36:40 [27027] DBG:tm:t_lookup_request: no transaction found
Jan 21 14:36:40 [27027] DBG:core:parse_headers: flags=200
Jan 21 14:36:40 [27027] DBG:rr:is_preloaded: is_preloaded: No
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if port 5066
matches port 5070
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if host==us:
14==13 &&  [80.228.245.138] == [212.6.123.118]
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if port 5066
matches port 5070
Jan 21 14:36:40 [27027] DBG:core:check_self: host != me
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [212.6.123.118] == [212.6.123.118]
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if port 5066
matches port 5060
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if host==us:
13==13 &&  [212.6.123.118] == [212.6.123.118]
Jan 21 14:36:40 [27027] DBG:core:grep_sock_info: checking if port 5066
matches port 5060
Jan 21 14:36:40 [27027] DBG:core:check_self: host != me
Jan 21 14:36:40 [27027] DBG:rr:after_loose: Topmost URI is NOT myself
Jan 21 14:36:40 [27027] DBG:rr:after_loose: URI to be processed:
'sip:212.6.123.118;lr=on;ftag=7w4sllx8cc'
Jan 21 14:36:40 [27027] DBG:rr:after_loose: Next URI is a loose router
Loose Route
Jan 21 14:36:40 [27027] DBG:tm:t_newtran: transaction on entrance=(nil)
Jan 21 14:36:40 [27027] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 21 14:36:40 [27027] DBG:core:get_hdr_field: content_length=0
Jan 21 14:36:40 [27027] DBG:core:get_hdr_field: found end of header
Jan 21 14:36:40 [27027] DBG:core:parse_headers: flags=78
Jan 21 14:36:40 [27027] DBG:tm:t_lookup_request: start searching:
hash=19447, isACK=0
Jan 21 14:36:40 [27027] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jan 21 14:36:40 [27027] DBG:tm:t_lookup_request: no transaction found


A strace on the cpu wasting process says nothing:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
27168 ruth      25   0 37328 3304 3076 R 98.8  0.4   0:07.32 openser
    1 root      16   0  1568  532  460 S  0.0  0.1   0:06.75 init
    2 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 migration/0
    3 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/0
    4 root      RT   0     0    0    0 S  0.0  0.0   0:00.02 watchdog/0
    5 root      10  -5     0    0    0 S  0.0  0.0   0:01.71 events/0
    6 root      10  -5     0    0    0 S  0.0  0.0   0:00.01 khelper
    7 root      10  -5     0    0    0 S  0.0  0.0   0:00.02 kthread
    9 root      10  -5     0    0    0 S  0.0  0.0   0:00.37 kblockd/0
   10 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kacpid
  103 root      13  -5     0    0    0 S  0.0  0.0   0:00.00 aio/0
  102 root      15   0     0    0    0 S  0.0  0.0   0:45.57 kswapd0
  691 root      11  -5     0    0    0 S  0.0  0.0   0:00.01 kseriod
 1640 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_0
 1725 root      15   0     0    0    0 S  0.0  0.0   0:17.81 kjournald
 1963 root      11  -4  2128  708  468 S  0.0  0.1   0:00.87 udevd
 2801 root      20   0     0    0    0 S  0.0  0.0   0:00.00
shpchpd_event
 2903 daemon    16  -2  1668  476  376 S  0.0  0.1   0:00.12 portmap
 3066 root      15   0     0    0    0 S  0.0  0.0   0:42.14 kjournald
 5063 root      16   0  1684  500  412 S  0.0  0.1   0:00.08 dd
 5065 klog      16   0  2408 1328  388 S  0.0  0.2   0:00.08 klogd
 5097 root      18   0 12552 2412 1364 S  0.0  0.3   0:00.02 slapd
 5171 root      15   0  1688  576  484 S  0.0  0.1   4:38.29
vmware-guestd
 5226 root      16   0  2644 1316 1064 S  0.0  0.2   0:00.03 mysqld_safe
 5299 mysql     16   0  135m  40m 4880 S  0.0  5.4   1:45.73 mysqld
 5300 root      16   0  1552  504  432 S  0.0  0.1   0:00.00 logger
 5417 root      16   0  4768 1056  756 S  0.0  0.1   0:00.12 sshd
 5456 root      16   0  2216  796  664 S  0.0  0.1   0:06.50 xinetd
 5473 root      18   0  1728  716  616 S  0.0  0.1   0:00.00 rpc.statd
 5555 root      16   0  8228 2092  980 S  0.0  0.3   0:15.42 sendmail-mta
ruth at vm-en-test0:~/tmp$ strace -p 27168
Process 27168 attached - interrupt to quit




When I start openser in no fork mode and within strace I got this at last
lines:

write(2, "Jan 21 14:39:05 [27054] DBG:tm:t"..., 72Jan 21 14:39:05 [27054]
DBG:tm:t_newtran: transaction on entrance=(nil)
) = 72
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:core"..., 71Jan 21 14:39:05 [27054]
DBG:core:parse_headers: flags=ffffffffffffffff
) = 71
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:core"..., 65Jan 21 14:39:05 [27054]
DBG:core:get_hdr_field: content_length=0
) = 65
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:core"..., 68Jan 21 14:39:05 [27054]
DBG:core:get_hdr_field: found end of header
) = 68
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:core"..., 57Jan 21 14:39:05 [27054]
DBG:core:parse_headers: flags=78
) = 57
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:tm:t"..., 86Jan 21 14:39:05 [27054]
DBG:tm:t_lookup_request: start searching: hash=19447, isACK=0
) = 86
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:tm:m"..., 82Jan 21 14:39:05 [27054]
DBG:tm:matching_3261: RFC3261 transaction matching failed
) = 82
time([1200922745])                      = 1200922745
write(2, "Jan 21 14:39:05 [27054] DBG:tm:t"..., 70Jan 21 14:39:05 [27054]
DBG:tm:t_lookup_request: no transaction found
) = 70


I tested it against an umodified (I extended avp aliases for using script
flags) openser 1.4  ... same problem.


regards
helmut



----------------------------------------------------------------------

Comment By: Henning Westerholt (henningw)
Date: 2008-01-21 04:05

Message:
Logged In: YES 
user_id=337916
Originator: NO

Hi Helmut,

i've tried to reproduce this bug on my machine. This config and sip
message (of course with adapted IP and user) works for me. I've tried
several permutations of IP and CFGs, unfortunally without any trace to the
bug you described. I get this debug message:

Jan 21 13:02:03 [1172] DBG:core:parse_msg: SIP Request:
Jan 21 13:02:03 [1172] DBG:core:parse_msg:  method:  <BYE>
Jan 21 13:02:03 [1172] DBG:core:parse_msg:  uri:    
<sip:80.228.245.138:5070>
Jan 21 13:02:03 [1172] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 21 13:02:03 [1172] DBG:core:parse_headers: flags=2
Jan 21 13:02:03 [1172] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-7rhl6qnns4ej>; state=6
Jan 21 13:02:03 [1172] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=17
Jan 21 13:02:03 [1172] DBG:core:parse_via: end of header reached, state=5
Jan 21 13:02:03 [1172] DBG:core:parse_headers: via found, flags=2
Jan 21 13:02:03 [1172] DBG:core:parse_headers: this is the first via
Jan 21 13:02:03 [1172] DBG:core:receive_msg: After parse_msg...
Jan 21 13:02:03 [1172] DBG:core:receive_msg: preparing to run routing
scripts...
Jan 21 13:02:03 [1172] DBG:tm:t_newtran: transaction on
entrance=0xffffffff
Jan 21 13:02:03 [1172] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 21 13:02:03 [1172] DBG:core:parse_to_param: tag=0082-00000054-0103i0
Jan 21 13:02:03 [1172] DBG:core:parse_to: end of header reached, state=29
Jan 21 13:02:03 [1172] DBG:core:parse_to: display={},
ruri={sip:12345 at sip0.en.ewetel.de;user=phone}
Jan 21 13:02:03 [1172] DBG:core:get_hdr_field: <To> [66];
uri=[sip:12345 at sip0.en.ewetel.de;user=phone]
Jan 21 13:02:03 [1172] DBG:core:get_hdr_field: to body
[<sip:12345 at sip0.en.ewetel.de;user=phone>]
Jan 21 13:02:03 [1172] DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE>
Jan 21 13:02:03 [1172] DBG:core:get_hdr_field: content_length=0
Jan 21 13:02:03 [1172] ERROR:tm:t_newtran: EoH not parsed
Jan 21 13:02:03 [1172] DBG:core:destroy_avp_list: destroying list (nil)
Jan 21 13:02:03 [1172] DBG:core:receive_msg: cleaning up

Could you please try again on your machine, and compare the debug output
that is reported? You could also try to attach with 'strace' to the server
process and look where its hangs.

Cheers,

Henning

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1876311&group_id=139143



More information about the Devel mailing list