[OpenSER-Devel] [ openser-Bugs-1808421 ] Serious Dialog Persistence
Problems
SourceForge.net
noreply at sourceforge.net
Mon Oct 8 09:50:39 CEST 2007
Bugs item #1808421, was opened at 2007-10-06 04:04
Message generated for change (Settings changed) made by bogdan_iancu
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1808421&group_id=139143
Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: ver devel
Status: Open
Resolution: None
>Priority: 7
Private: No
Submitted By: reticent (unspin)
>Assigned to: Bogdan (bogdan_iancu)
Summary: Serious Dialog Persistence Problems
Initial Comment:
1. Dialogs aren't removed from the database when a BYE message is received immediately after a call is established (call, then hang up), if you wait 5 seconds before hanging up then the record is properly removed from the database
A timer process is created which increments the ref count on that specific dialog, so the mechanism to remove the record is skipped over due to this none zero ref count
bug1: where the timer is created, and a bye comes in before the timer
expires, therefore the dialog is never distroyed due to dlg->ref
greater than 0.
Oct 6 00:42:21 spb1 OpenSER[4732]: core:forward_request: sending: ACK
sip:*33 at 207.232.98.31:5080 SIP/2.0 Via: SIP/2.0/UDP
207.232.98.31:15061;branch=z9hG4bKa882.d4d47456.2 Via: SIP/2.0/UDP
192.168.99.63:5070;rport=5070;received=207.232.98.114;branch=z9hG4bK-1fdef174
From: "Peter" <sip:200110002497 at spb1.hq.galnet.ca:15061>;tag=3d58c4a0e48788d7o1
To: <sip:*33 at spb1.hq.galnet.ca:15061>;tag=as3d3956fa Call-ID:
bbab9314-e863ecf3 at 192.168.99.63 CSeq: 102 ACK Max-Forwards: 14
Proxy-Authorization: Digest
username="200110002497",realm="van.galnet.ca",nonce="4706db19f9092f764ca009cd617d666f2b333087",uri="sip:*33 at spb1.hq.galnet.ca:15061",algorithm=MD5,response="abc88944612991d306758a7e5f52406e",qop=auth,nc=00000001,cnonce="69c15487"
Contact: "Peter" <sip:200110002497 at 207.232.98.114:5070> User-Agent:
Linksys/SPA962-5.1.7 Content-Length: 0 .
Oct 6 00:42:21 spb1 OpenSER[4732]: core:forward_request: orig.
len=774, new_len=785, proto=1
Oct 6 00:42:21 spb1 OpenSER[4732]: DEBUG:tm:UNREF_UNSAFE: after is 0
Oct 6 00:42:21 spb1 OpenSER[4732]: core:destroy_avp_list: destroying list (nil)
Oct 6 00:42:21 spb1 OpenSER[4732]: core:receive_msg: cleaning up
Oct 6 00:42:22 spb1 OpenSER[4746]: DEBUG: timer
routine:4,tl=0xb6b9625c next=(nil), timeout=744500000
Oct 6 00:42:22 spb1 asterisk[3157]: VERBOSE[5059]: -- Executing
DateTime("SIP/15061-08159568", "") in new stack
Oct 6 00:42:22 spb1 asterisk[3157]: DEBUG[5059]: say.c:2988 in
ast_say_date_with_format_en: Parsing A (offset 0) in ABdY 'digits/at'
IMp
Oct 6 00:42:22 spb1 asterisk[3157]: VERBOSE[5059]: -- Playing
'digits/day-6' (language 'en')
Oct 6 00:42:23 spb1 OpenSER[4736]: core:udp_rcv_loop: probing packet
received from 207.232.98.114 52755
Oct 6 00:42:23 spb1 asterisk[3157]: DEBUG[5059]: say.c:2988 in
ast_say_date_with_format_en: Parsing B (offset 1) in ABdY 'digits/at'
IMp
Oct 6 00:42:23 spb1 asterisk[3157]: VERBOSE[5059]: -- Playing
'digits/mon-9' (language 'en')
Oct 6 00:42:24 spb1 asterisk[3157]: DEBUG[5059]: say.c:2988 in
ast_say_date_with_format_en: Parsing d (offset 2) in ABdY 'digits/at'
IMp
Oct 6 00:42:24 spb1 asterisk[3157]: VERBOSE[5059]: -- Playing
'digits/h-6' (language 'en')
Oct 6 00:42:25 spb1 asterisk[3157]: DEBUG[5059]: say.c:2988 in
ast_say_date_with_format_en: Parsing Y (offset 3) in ABdY 'digits/at'
IMp
Oct 6 00:42:25 spb1 asterisk[3157]: VERBOSE[5059]: -- Playing
'digits/2' (language 'en')
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_msg: SIP Request:
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_msg: method: <BYE>
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_msg: uri:
<sip:*33 at 207.232.98.31:5080>
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_msg: version: <SIP/2.0>
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=2
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_via_param: found param
type 232, <branch> = <z9hG4bK-7bf12383>; state=16
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_via: end of header
reached, state=5
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: via found, flags=2
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: this is the first via
Oct 6 00:42:25 spb1 OpenSER[4740]: core:receive_msg: After parse_msg...
Oct 6 00:42:25 spb1 OpenSER[4740]: core:receive_msg: preparing to run
routing scripts...
Oct 6 00:42:25 spb1 OpenSER[4740]:
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=10
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to_param: tag=3d58c4a0e48788d7o1
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to: end of header
reached, state=29
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to: display={"Peter"},
ruri={sip:200110002497 at spb1.hq.galnet.ca:15061}
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=8
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to_param: tag=as3d3956fa
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to: end of header
reached, state=29
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_to: display={},
ruri={sip:*33 at spb1.hq.galnet.ca:15061}
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: <To> [50];
uri=[sip:*33 at spb1.hq.galnet.ca:15061]
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: to body
[<sip:*33 at spb1.hq.galnet.ca:15061>]
Oct 6 00:42:25 spb1 OpenSER[4740]: [200110002497] Route{main}: New
Message METHOD: [BYE] TO: [*33]
Oct 6 00:42:25 spb1 OpenSER[4740]: [200110002497] Route{main}: Source
IP: [207.232.98.114]
Oct 6 00:42:25 spb1 OpenSER[4740]: [200110002497] Route{main};
Request URI - [sip:*33 at 207.232.98.31:5080] -
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=80
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: cseq <CSeq>: <103> <BYE>
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: content_length=0
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: found end of header
Oct 6 00:42:25 spb1 OpenSER[4740]: core:pv_get_contact: no contact header!
Oct 6 00:42:25 spb1 OpenSER[4740]: [200110002497] Route{main}:
Contact Header: [<null>]
Oct 6 00:42:25 spb1 OpenSER[4740]:
################################################################################
Oct 6 00:42:25 spb1 OpenSER[4740]: maxfwd:is_maxfwd_present: value = 15
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=200
Oct 6 00:42:25 spb1 OpenSER[4740]: is_preloaded: No
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
host==us: 13==13 && [207.232.98.31] == [207.232.98.31]
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
port 15061 matches port 5080
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
host==us: 13==13 && [207.232.98.31] == [207.232.98.31]
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
port 15061 matches port 5080
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
host==us: 13==9 && [207.232.98.31] == [127.0.0.1]
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
port 15061 matches port 5080
Oct 6 00:42:25 spb1 OpenSER[4740]: core:check_self: host != me
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
host==us: 13==13 && [207.232.98.31] == [207.232.98.31]
Oct 6 00:42:25 spb1 OpenSER[4740]: core:grep_sock_info: checking if
port 15061 matches port 15061
Oct 6 00:42:25 spb1 OpenSER[4740]: after_loose: Topmost route URI:
'sip:207.232.98.31:15061;lr;ftag=3d58c4a0e48788d7o1;bid=bPP.x3v.E7g;nid=UX0.v9G.Wu3'
is me
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=200
Oct 6 00:42:25 spb1 OpenSER[4740]: core:get_hdr_field: found end of header
Oct 6 00:42:25 spb1 OpenSER[4740]: find_next_route: No next Route HF found
Oct 6 00:42:25 spb1 OpenSER[4740]: after_loose: No next URI found
Oct 6 00:42:25 spb1 OpenSER[4740]: DBG:rr:run_rr_callbacks: callback
id 0 entered with
<lr;ftag=3d58c4a0e48788d7o1;bid=bPP.x3v.E7g;nid=UX0.v9G.Wu3>
Oct 6 00:42:25 spb1 OpenSER[4740]: core:parse_headers: flags=48
Oct 6 00:42:25 spb1 OpenSER[4740]: dialog:internal_get_dlg: dialog
callid='bbab9314-e863ecf3 at 192.168.99.63' found on entry 9, dir=2
Oct 6 00:42:25 spb1 OpenSER[4740]: dialog:next_state_dlg: dialog
0xb6b94240 changed from state 4 to state 5, due event 7
Oct 6 00:42:25 spb1 OpenSER[4740]: dialog:dlg_onroute: BYE
successfully processed
Oct 6 00:42:25 spb1 OpenSER[4740]: dialog:unref_dlg: unref dlg
0xb6b94240 with 2 -> 1
2. When the dialog goes from state 5 to state 5 (which occurs after the first bug mentioned above, several seconds after the BYE message is received) another attempt is made by OpenSER to delete the dialog from the database, however the context at that point is that of a timer process and not an openser child process so there is no database connection handle available
BUG2: On the timer expire no db handle after the BYE.
Oct 6 00:42:25 spb1 OpenSER[4740]: core:_shm_resize: resize(0) called
Oct 6 00:42:25 spb1 OpenSER[4740]: DEBUG: add_to_tail_of_timer[2]:
0xb6b93470 (752)
Oct 6 00:42:25 spb1 OpenSER[4740]: DEBUG:tm:relay_reply: sent
buf=0x81af688: SIP/2.0 2..., shmem=0xb6b95758: SIP/2.0 2
Oct 6 00:42:25 spb1 OpenSER[4740]: DEBUG: cleanup_uac_timers: RETR/FR
timers reset
Oct 6 00:42:25 spb1 OpenSER[4740]: DEBUG:tm:UNREF_UNSAFE: after is 0
Oct 6 00:42:25 spb1 OpenSER[4740]: core:destroy_avp_list: destroying list (nil)
Oct 6 00:42:25 spb1 OpenSER[4740]: core:receive_msg: cleaning up
Oct 6 00:42:26 spb1 OpenSER[4746]: DEBUG: timer
routine:2,tl=0xb6b96158 next=(nil), timeout=748
Oct 6 00:42:26 spb1 OpenSER[4746]: DEBUG: wait_handler : removing
0xb6b96110 from table
Oct 6 00:42:26 spb1 OpenSER[4746]: DEBUG: delete transaction 0xb6b96110
Oct 6 00:42:26 spb1 OpenSER[4746]: DBG: trans=0xb6b96110, callback
type 2048, id 0 entered
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:next_state_dlg: unref dlg
0xb6b94240 with 1 -> 0
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:next_state_dlg: destroying a dialog
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:destroy_dlg: destroing
dialog 0xb6b94240
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:remove_dialog_from_db:
trying to remove a dialog, update_flag is 0
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:use_dialog_table: invalid
database handle
Oct 6 00:42:26 spb1 OpenSER[4746]: dialog:next_state_dlg: dialog
0xb6b94240 changed from state 5 to state 5, due event 1
Oct 6 00:42:26 spb1 OpenSER[4746]: DEBUG: wait_handler : done
Oct 6 00:42:26 spb1 OpenSER[4746]: DEBUG: timer
routine:4,tl=0xb6b93574 next=(nil), timeout=748100000
----------------------------------------------------------------------
Comment By: reticent (unspin)
Date: 2007-10-06 04:07
Message:
Logged In: YES
user_id=1568212
Originator: YES
Here is the dialog module configuration we are using, we were able to
reproduce both these issues with a copy of TRUNK checked out this
afternoon
# Documentation says default is 0, but it's -1 according to source..
wth? breaks...
modparam("dialog", "dlg_flag", 20)
# Number of buckets in the hash table (don't change this without
clearing the dialog table)
modparam("dialog", "hash_size", 16)
# Collect Stats
modparam("dialog", "enable_stats", 1)
# AVP used to specify a custom timeout for the dialog
# - Not sure if this will actually tear the dialog down (might need to
use the b2bua module)
# modparam("dialog", "timeout_avp", "$avp(i:10)")
# Default dialog timeout
# modparam("dialog", "default_timeout", 43200)
# Set the dialog matching mode
# 2 - Use the SIP elements
modparam("dialog", "dlg_match_mode", 2)
# Dialog Database Mode
# 2 - Delayed Mode
modparam("dialog", "db_mode", 1)
# How often OpenSER syncs Dialogs to the database
modparam("dialog", "db_update_period", 1)
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1808421&group_id=139143
More information about the Devel
mailing list