[OpenSER-Devel] [ openser-Bugs-1876311 ] OpenSER Message of Death?
SourceForge.net
noreply at sourceforge.net
Tue Jan 22 12:03:17 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 04:03
Message:
Logged In: NO
Hi, ok I found my problem ...
has nothing to do with ubuntu, but with an error in my openser config. I
included an old TM module, which hasn't the magic line
"new_msg->sibling=0;" in sip_msg.c
So we can close this case.
Thank u 4 ur help. If we meet someday I will spend a beer.
cheers
Helmut.
----------------------------------------------------------------------
Comment By: Nobody/Anonymous (nobody)
Date: 2008-01-22 02:44
Message:
Logged In: NO
I played around with gdb and found that a list 523 shows this:
510 for( hdr=org_msg->headers,last_hdr=0 ; hdr ; hdr=hdr->next
)
(gdb)
511 {
512 new_hdr = (struct hdr_field*)p;
513 memcpy(new_hdr, hdr, sizeof(struct hdr_field) );
514 p += ROUND4(sizeof( struct hdr_field));
515 new_hdr->name.s = translate_pointer(new_msg->buf,
org_msg->buf,
516 hdr->name.s);
517 new_hdr->body.s = translate_pointer(new_msg->buf,
org_msg->buf,
518 hdr->body.s);
519 /* by default, we assume we don't understand this
header in TM
520 and better set it to zero; if we do, we will
set a specific
(gdb)
521 value in the following switch statement
522 */
523 new_hdr->parsed=0;
524
525 switch (hdr->type)
that means there is no line "new_msg->sibling=0;"
I added some debug ouput via LM_INFO(), but even that isn't in the code
listet in gdb ...
When I do the change in source code, make PREFIX=... install compiled the
changes and the binary in sbin/ has a new timestamp ...
----------------------------------------------------------------------
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