27 Nov
2009
27 Nov
'09
1:41 p.m.
Hello,
today I've tested the current version of sip-router (version: ser 2.99.99-pre3
(i386/linux) 470d30) again with the dialog module. I found that the problem is independent
of presence/dialog-state information based on subscribe/notify. As soon as the dialog
module and the setflag() function for the dlg_flag is used, the server seems to have
problems with the BYE message / closing the dialog.
I've done debugging with dbg and the backtrace of the tool is as follows:
(gdb) bt
#0 0xb7f1d424 in __kernel_vsyscall ()
#1 0xb7dcd640 in raise () from /lib/i686/cmov/libc.so.6
#2 0xb7dcf018 in abort () from /lib/i686/cmov/libc.so.6
#3 0x08153dae in qm_free (qm=0xb5773000, p=0xb5910068, file=0xb794b759 "dialog:
dlg_hash.c", func=0xb794c035 "destroy_dlg", line=163) at
mem/q_malloc.c:447
#4 0xb7934549 in destroy_dlg (dlg=0xb590ff38) at dlg_hash.c:163
#5 0xb7936769 in unref_dlg (dlg=0xb590ff38, cnt=1) at dlg_hash.c:565
#6 0xb793b21d in profile_cleanup (msg=0x82c9d8c, flags=2147483649, param=0x0) at
dlg_profile.c:307
#7 0x080e9668 in exec_post_script_cb (msg=0x82c9d8c, type=REQUEST_CB_TYPE) at
script_cb.c:195
#8 0x080c5228 in receive_msg (
buf=0x8258940 "BYE sip:5002@10.16.48.60:5071 SIP/2.0\r\nVia: SIP/2.0/UDP
10.16.48.60:5072;rport;branch=z9hG4bK2740720758\r\nRoute:
<sip:10.16.48.205;lr=on;did=ad4.5f3b1a65>\r\nFrom:
<sip:5003@10.16.48.205>;tag=3876329704-"..., len=463, rcv_info=0xbfd38bd8) at
receive.c:211
#9 0x08145bc3 in udp_rcv_loop () at udp_server.c:527
#10 0x080997a7 in main_loop () at main.c:1454
#11 0x0809c56b in main (argc=3, argv=0xbfd38e64) at main.c:2251
(gdb)
The original server error messages were:
#######################################################################
1(30934) DEBUG: <core> [forward.c:517]: orig. len=462, new_len=457, proto=1
1(30934) DEBUG: dialog [dlg_hash.c:565]: unref dlg 0xb590ff38 with 1 -> 2
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [usr_avp.c:636]: DEBUG:destroy_avp_list: destroying list
(nil)
1(30934) DEBUG: <core> [receive.c:267]: receive_msg: cleaning up
3(30936) DEBUG: dialog [dlg_hash.c:622]: unref dlg 0xb590ff38 with 1 -> 1
3(30936) DEBUG: dialog [dlg_hash.c:734]: dialog 0xb590ff38 changed from state 4 to state
4, due event 1
1(30934) DEBUG: <core> [parser/msg_parser.c:621]: SIP Request:
1(30934) DEBUG: <core> [parser/msg_parser.c:623]: method: <BYE>
1(30934) DEBUG: <core> [parser/msg_parser.c:625]: uri:
<sip:5002@10.16.48.60:5071>
1(30934) DEBUG: <core> [parser/msg_parser.c:627]: version: <SIP/2.0>
1(30934) DEBUG: <core> [parser/parse_via.c:1287]: Found param type 235,
<rport> = <n/a>; state=6
1(30934) DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232,
<branch> = <z9hG4bK2740720758>; state=16
1(30934) DEBUG: <core> [parser/parse_via.c:2300]: end of header reached, state=5
1(30934) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers: Via found,
flags=2
1(30934) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: this is the first
via
1(30934) DEBUG: <core> [receive.c:140]: After parse_msg...
1(30934) DEBUG: <core> [receive.c:179]: preparing to run routing scripts...
1(30934) DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param:
tag=1718402625-3958280-1259324882918
1(30934) DEBUG: <core> [parser/parse_to.c:781]: end of header reached, state=29
1(30934) DEBUG: <core> [parser/msg_parser.c:185]: DEBUG: get_hdr_field: <To>
[67]; uri=[sip:5002@10.16.48.205]
1(30934) DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: to body [test
<sip:5002@10.16.48.205>]
1(30934) DEBUG: <core> [parser/msg_parser.c:165]: get_hdr_field: cseq <CSeq>:
<21> <BYE>
1(30934) DEBUG: maxfwd [mf_funcs.c:85]: value = 70
1(30934) DEBUG: siputils [checks.c:76]: totag found
1(30934) DEBUG: rr [loose.c:85]: is_preloaded: No
1(30934) DEBUG: <core> [socket_info.c:491]: grep_sock_info - checking if host==us:
11==12 && [10.16.48.60] == [10.16.48.205]
1(30934) DEBUG: <core> [socket_info.c:494]: grep_sock_info - checking if port 5060
matches port 5071
1(30934) DEBUG: <core> [forward.c:362]: check_self: host != me
1(30934) DEBUG: <core> [socket_info.c:491]: grep_sock_info - checking if host==us:
12==12 && [10.16.48.205] == [10.16.48.205]
1(30934) DEBUG: <core> [socket_info.c:494]: grep_sock_info - checking if port 5060
matches port 5060
1(30934) DEBUG: rr [loose.c:781]: Topmost route URI:
'sip:10.16.48.205;lr=on;did=ad4.5f3b1a65' is me
1(30934) DEBUG: <core> [parser/msg_parser.c:199]: DEBUG: get_hdr_body :
content_length=0
1(30934) DEBUG: <core> [parser/msg_parser.c:101]: found end of header
1(30934) DEBUG: rr [loose.c:257]: No next Route HF found
1(30934) DEBUG: rr [loose.c:800]: No next URI found
1(30934) DEBUG: rr [rr_cb.c:97]: callback id 0 entered with
<lr=on;did=ad4.5f3b1a65>
1(30934) DEBUG: dialog [dlg_handlers.c:787]: route param is 'ad4.5f3b1a65'
(len=12)
1(30934) DEBUG: dialog [dlg_hash.c:374]: ref dlg 0xb590ff38 with 1 -> 2
1(30934) DEBUG: dialog [dlg_hash.c:376]: dialog id=1453437941 found on entry 1242
1(30934) DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param:
tag=3876329704-3958320-1259324882934
1(30934) DEBUG: <core> [parser/parse_to.c:781]: end of header reached, state=29
1(30934) DEBUG: dialog [dlg_hash.c:734]: dialog 0xb590ff38 changed from state 4 to state
5, due event 7
1(30934) DEBUG: dialog [dlg_handlers.c:873]: BYE successfully processed
1(30934) DEBUG: dialog [dlg_hash.c:565]: unref dlg 0xb590ff38 with 2 -> 0
1(30934) DEBUG: dialog [dlg_hash.c:565]: ref <=0 for dialog 0xb590ff38
1(30934) DEBUG: dialog [dlg_hash.c:135]: destroing dialog 0xb590ff38
1(30934) DEBUG: dialog [dlg_hash.c:151]: removed timer for dlg 0xb590ff38
[1242:1453437941] with clid '3569445337-3958280-1259324882918(a)10.16.48.60' and
tags '1718402625-3958280-1259324882918'
'3876329704-3958320-1259324882934'
1(30934) DEBUG: tm [t_lookup.c:1387]: DEBUG: t_newtran: msg id=6 , global msg id=5 , T on
entrance=(nil)
1(30934) DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching: hash=62717,
isACK=0
1(30934) DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
1(30934) DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
1(30934) DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb590f2b8, callback type 1, id 0 entered
1(30934) DEBUG: tm [t_hooks.c:335]: DBG: trans=0xb590f2b8, callback type 1, id 0 entered
1(30934) DEBUG: <core> [msg_translator.c:207]: check_via_address(10.16.48.60,
10.16.48.60, 0)
1(30934) DEBUG: tm [t_funcs.c:386]: SER: new transaction fwd'ed
1(30934) DEBUG: dialog [dlg_hash.c:565]: unref dlg 0xb590ff38 with 1 -> -1
1(30934) CRITICAL: dialog [dlg_hash.c:565]: bogus ref -1 with cnt 1 for dlg 0xb590ff38
[1242:1453437941] with clid '3569445337-3958280-1259324882918(a)10.16.48.60' and
tags '1718402625-3958280-1259324882918'
'3876329704-3958320-1259324882934'
1(30934) DEBUG: dialog [dlg_hash.c:565]: ref <=0 for dialog 0xb590ff38
1(30934) DEBUG: dialog [dlg_hash.c:135]: destroing dialog 0xb590ff38
1(30934) DEBUG: dialog [dlg_hash.c:151]: removed timer for dlg 0xb590ff38
[1242:1453437941] with clid '3569445337-3958280-1259324882918(a)10.16.48.60' and
tags '1718402625-3958280-1259324882918'
'3876329704-3958320-1259324882934'
1(30934) : <core> [mem/q_malloc.c:446]: BUG: qm_free: freeing already freed
pointer, first free: dialog: dlg_hash.c: destroy_dlg(163) - aborting
0(30933) ALERT: <core> [main.c:729]: child process 30934 exited by a signal 6
0(30933) ALERT: <core> [main.c:732]: core was generated
0(30933) INFO: <core> [main.c:744]: INFO: terminating due to SIGCHLD
5(30938) INFO: <core> [main.c:795]: INFO: signal 15 received
4(30937) INFO: <core> [main.c:795]: INFO: signal 15 received
3(30936) INFO: <core> [main.c:795]: INFO: signal 15 received
2(30935) INFO: <core> [main.c:795]: INFO: signal 15 received
0(30933) DEBUG: presence_xml [presence_xml.c:332]: start
0(30933) DEBUG: <core> [db_pool.c:102]: removing connection from the pool
0(30933) DEBUG: tm [t_funcs.c:120]: DEBUG: tm_shutdown : start
0(30933) DEBUG: tm [t_funcs.c:123]: DEBUG: tm_shutdown : emptying hash table
0(30933) DEBUG: tm [t_funcs.c:125]: DEBUG: tm_shutdown : removing semaphores
0(30933) DEBUG: tm [t_funcs.c:127]: DEBUG: tm_shutdown : destroying tmcb lists
0(30933) DEBUG: tm [t_funcs.c:130]: DEBUG: tm_shutdown : done
0(30933) DEBUG: <core> [mem/shm_mem.c:236]: shm_mem_destroy
0(30933) DEBUG: <core> [mem/shm_mem.c:239]: destroying the shared memory lock
0(30933) DEBUG: <core> [main.c:748]: terminating due to SIGCHLD
#######################################################################
I hope this information helps solving the problem with the dialog module. I will follow up
with testing the presence/dialog-state notifications only when the dialog module itself
will work fine. There seems to be another problem in these modules.....
regards,
Klaus
-------- Original-Nachricht --------
Datum: Wed, 25 Nov 2009 18:25:26 +0100
Von: Daniel-Constantin Mierla <miconda(a)gmail.com>
An: klaus.feichtinger(a)gmx.net
CC: sr-users(a)lists.sip-router.org
Betreff: Re: [SR-Users] Problems with PRESENCE/DIALOG functionality in sip-router
Hello,
can you get the latest git. I just did a fix, I haven't tested the
dialoginfo presence module yet, the problem was in some checks in tm.
However, not sure the crash was related. Can you send the backtrace?
gdb /path/to/kamailio core
then: bt
Cheers,
Daniel
On 25.11.2009 8:42 Uhr, klaus.feichtinger(a)gmx.net wrote:
--
Jetzt kostenlos herunterladen: Internet Explorer 8 und Mozilla Firefox 3.5 -
sicherer, schneller und einfacher! http://portal.gmx.net/de/go/chbrowser
Hi all,
I've tested the current release candidate for Kamailio these days and
found
that the presence/dialog state functionality is not given in the
current version.
The first (and worst) difference to the latest stable release is that
the handling
of "setflag(X)" for tracing the dialogs resulted in a crash of
kamailio with following error message:
********************** EXCERPT ******************
Nov 24 13:35:47 lennysrv /usr/local/sbin/kamailio[13814]: : tm
[t_hooks.c:190]:
BUG:tm:register_tmcb: callback type TMCB_REQUEST_IN can't be
register along with types
Nov 24 13:35:47 lennysrv
/usr/local/sbin/kamailio[13814]: ERROR: dialog
[dlg_handlers.c:615]: failed cache
in T the shortcut to dlg
Nov 24 13:35:53 lennysrv
/usr/local/sbin/kamailio[13815]: NOTICE: acc
[acc.c:275]: ACC: call missed:
timestamp=1259134133;method=INVITE;from_tag=4051501197-3958320-1259134127622;to_tag=3762694574-3958280-1259134127622;call_id=140363298-3958320-1259134127622(a)10.16.48.60;code=603;reason=Decline;src_user=5003;src_domain=10.16.48.205;dst_ouser=5002;dst_user=5002;dst_domain=10.16.48.60
Nov 24 13:35:56 lennysrv
/usr/local/sbin/kamailio[13815]: INFO:
pua_usrloc [ul_publish.c:203]: should not
send ul publish
Nov 24 13:35:56 lennysrv
/usr/local/sbin/kamailio[13815]: INFO:
<script>: --- pua-set-publish() was
executed ---
Nov 24 13:35:58 lennysrv kernel: [176699.348059]
kamailio[13821]:
segfault at c0c0c0c0 ip b7de43b3 sp bfb03eb8 error 5 in
libc-2.7.so[b7d6e000+155000]
Nov 24 13:35:58 lennysrv
/usr/local/sbin/kamailio[13837]: : <core>
[pass_fd.c:283]: ERROR: receive_fd:
EOF on 12
Nov 24 13:35:58 lennysrv
/usr/local/sbin/kamailio[13812]: ALERT: <core>
[main.c:721]: child process
13821 exited by a signal 11
Nov 24 13:35:58 lennysrv
/usr/local/sbin/kamailio[13812]: ALERT: <core>
[main.c:724]: core was
generated
Nov 24 13:35:58 lennysrv
/usr/local/sbin/kamailio[13812]: INFO: <core>
[main.c:736]: INFO: terminating
due to SIGCHLD
Nov 24 13:35:58 lennysrv
/usr/local/sbin/kamailio[13814]: INFO: <core>
[main.c:787]: INFO: signal 15
received
***************************************************
However, the module documentation of the source code (READMEs) does not
include
major news. The configuration is "the same" (regarding
handle_publish, handle_subscribe, pua_set_publish) as I've used in the
kamailio-1.5.3
version. But - no NOTIFY messages with XML bodies are sent to the
subscribers / watchers. Instead of using the setflag(X) method I´ve tried using the
method "dlg_setflag(X)" for prohibiting crashes - that was accepted by
kamailio.
Were these modules tested (in combination with the dialog module) in the
new
version 3.0 RC1?
- presence
- presence_xml
- presence_dialoginfo
- pua
- pua_dialoginfo
- pua_usrloc
It does not work in the SER variant of sip-router, too. Yesterday I've
downloaded the current version with GIT, compiled the code, adapted the
configuration. But the result is the same as with kamailio-3 RC1 (crash and no
XML).
For being sure that I have not made any mistake in the configuration,
I've
tested the functionality in the version 1.5.3 of Kamailio today. It
works fine - the subscribers receive NOTIFY messages with XML body after every
PRESENCE and DIALOG state change.
Can anybody give me a hint? Thanks in advance!
regards,
Klaus
P.S. the tested versions:
PROBLEMS:
========
version: kamailio 3.0.0-rc1 (i386/linux) 78f069
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, DISABLE_NAGLE,
USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC,
USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
USE_DST_BLACKLIST, HAVE_RESOLV_RES
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.
@(#) $Id$
main.c compiled on 13:34:37 Nov 20 2009 with gcc 4.3.2
version: ser 2.99.99-pre3 (i386/linux)
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, DISABLE_NAGLE,
USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC,
USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
USE_DST_BLACKLIST, HAVE_RESOLV_RES
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.
@(#) $Id$
main.c compiled on 11:12:49 Nov 23 2009 with gcc 4.3.2
SUCCESS:
=======
version: kamailio 1.5.3-notls (i386/linux)
flags: STATISTICS, USE_IPV6, USE_TCP, DISABLE_NAGLE, USE_MCAST,
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, PKG_SIZE 4194304
poll method support: poll, epoll_lt, epoll_et,
sigio_rt, select.
svnrevision: unknown
@(#) $Id: main.c 5608 2009-02-13 16:48:17Z henningw $
main.c compiled on 13:31:21 Nov 24 2009 with gcc 4.3.2
--
Daniel-Constantin Mierla
* http://www.asipto.com/