[SR-Users] Problems with PRESENCE/DIALOG functionality in sip-router
Klaus Feichtinger
klaus.feichtinger at gmx.net
Fri Nov 27 13:41:07 CET 2009
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 at 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 at 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 at 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 at 10.16.48.205]
1(30934) DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: to body [test <sip:5002 at 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 at 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 at 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 at 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 at gmail.com>
> An: klaus.feichtinger at gmx.net
> CC: sr-users at 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 at gmx.net wrote:
> > 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 at 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/
--
Jetzt kostenlos herunterladen: Internet Explorer 8 und Mozilla Firefox 3.5 -
sicherer, schneller und einfacher! http://portal.gmx.net/de/go/chbrowser
More information about the sr-users
mailing list