[SR-Users] Problems with PRESENCE/DIALOG functionality in sip-router
Klaus Feichtinger
klaus.feichtinger at gmx.net
Fri Nov 27 22:36:57 CET 2009
Hello,
with this "last" version the fault with the dialog flag is solved. I've tested with this version:
"version: kamailio 3.0.0-rc2 (i386/linux) 9dca82"
However, the problem with presence/dialog-state notification is still open. I will make ongoing tests next week.
Thx for the fix!
regards,
Klaus
-------- Original-Nachricht --------
> Datum: Fri, 27 Nov 2009 14:58:39 +0100
> Von: Daniel-Constantin Mierla <miconda at gmail.com>
> An: Klaus Feichtinger <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,
>
> 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/
--
GRATIS für alle GMX-Mitglieder: Die maxdome Movie-FLAT!
Jetzt freischalten unter http://portal.gmx.net/de/go/maxdome01
More information about the sr-users
mailing list