[SR-Users] Problems with PRESENCE/DIALOG functionality in sip-router
Daniel-Constantin Mierla
miconda at gmail.com
Fri Nov 27 14:58:39 CET 2009
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 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/
>>
>
>
--
Daniel-Constantin Mierla
* http://www.asipto.com/
More information about the sr-users
mailing list