Hello,
what I expressed in my previous email, didn't seem related. Hopefully, thanks to your debug info, I was able to find and fix it. Please get the kamailio_3.0 branch from git and test again.
http://www.kamailio.org/dokuwiki/doku.php/install:kamailio-3.0.x-from-git
Thanks, Daniel
On 27.11.2009 13:41 Uhr, Klaus Feichtinger wrote:
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@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@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@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@gmail.com An: klaus.feichtinger@gmx.net CC: sr-users@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@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@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/