[OpenSER-Devel] [ openser-Bugs-1727883 ] missleading BUG log for
PRACK generated by the dialog module
SourceForge.net
noreply at sourceforge.net
Wed Jul 11 09:36:00 CEST 2007
Bugs item #1727883, was opened at 2007-05-29 23:08
Message generated for change (Comment added) made by bogdan_iancu
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1727883&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 1.2.x
Status: Open
Resolution: Accepted
Priority: 5
Private: No
Submitted By: Ovidiu Sas (osas)
Assigned to: Bogdan (bogdan_iancu)
Summary: missleading BUG log for PRACK generated by the dialog module
Initial Comment:
For every PRACK message, the dialog module is generating the following bogus probe:
BUG:next_state_dlg: bogus event 7 in state 2
bogus event: DLG_EVENT_REQ (PRACK in this case)
state: DLG_STATE_EARLY
----------------------------------------------------------------------
>Comment By: Bogdan (bogdan_iancu)
Date: 2007-07-11 10:36
Message:
Logged In: YES
user_id=1275325
Originator: NO
I need to take a closer look - could you please send me privately the logs
and trace for the whole call (INVITE+replies+PRACK) ?
Thanks and regards,
Bogdan
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2007-07-06 20:03
Message:
Logged In: YES
user_id=1395524
Originator: YES
Here are the relevant logs:
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: SIP Reply (status):
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: version: <SIP/2.0>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: status: <200>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: reason: <OK>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: flags=2
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: Found param type 232,
<branch> = <z9hG4bK00d9.5fa3e38.0>; state=16
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: end of header reached,
state=5
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: Via found,
flags=2
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: this is the
first via
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 1,
name=<Via>, body=<SIP/2.0/UDP 10.110.20.1;branch=z9hG4bK00d9.5fa3e38.0>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: first via: <SIP/2.0/UDP>
<10.110.20.1:(0)>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: ;<>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: exiting parse_msg
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: After parse_msg...
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:forward_reply: found
module tm, passing reply to it
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: t_check:
start=0xffffffff
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: flags=22
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: Found param type 232,
<branch> = <z9hG4bK00d9.7030f716.0>; state=16
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: end of header reached,
state=5
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: Via found,
flags=22
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: this is the
second via
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 1,
name=<Via>, body=<SIP/2.0/UDP 10.110.16.7;branch=z9hG4bK00d9.7030f716.0>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: Found param type 232,
<branch> = <z9hG4bK00d9.9db63ff.0>; state=16
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: end of header reached,
state=5
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: Via found,
flags=22
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 1,
name=<Via>, body=<SIP/2.0/UDP 10.110.1.130;branch=z9hG4bK00d9.9db63ff.0>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: end of header reached,
state=5
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: Via found,
flags=22
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 1,
name=<Via>, body=<SIP/2.0/UDP 10.111.3.241:5060>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 10,
name=<Record-Route>, body=<<sip:10.110.20.1;r2=on;lr;ftag=299341AC-1E61>>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 10,
name=<Record-Route>, body=<<sip:10.110.17.8;r2=on;lr;ftag=299341AC-1E61>>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 10,
name=<Record-Route>, body=<<sip:10.110.16.7;lr;ftag=299341AC-1E61>>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 10,
name=<Record-Route>, body=<<sip:10.110.1.130;r2=on;lr;ftag=299341AC-1E61>>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 10,
name=<Record-Route>, body=<<sip:10.111.5.30;r2=on;lr;ftag=299341AC-1E61>>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 4,
name=<From>, body=<<sip:4163836062 at 10.111.3.241>;tag=299341AC-1E61>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: add_param: tag=df28
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:parse_to:end of
header reached, state=29
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DBUG:parse_to: display={},
ruri={sip:4165863543 at 10.111.5.30}
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: get_hdr_field: <To>
[39]; uri=[sip:4165863543 at 10.111.5.30]
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: to body
[<sip:4165863543 at 10.111.5.30>]
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 3,
name=<To>, body=<<sip:4165863543 at 10.111.5.30>;tag=df28>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 6,
name=<Call-ID>, body=<C3FBC6C7-2B4C11DC-BE7BCD6C-D251F883 at 10.111.3.241>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: get_hdr_field: cseq <CSeq>:
<102> <PRACK>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 5,
name=<CSeq>, body=<102 PRACK>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: t_reply_matching:
hash 40192 label 138296053 branch 0
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:tm:REF_UNSAFE: after
is 1
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: t_reply_matching:
reply matched (T=0xb5ba4218)!
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: t_check:
end=0xb5ba4218
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:tm:reply_received:
org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: reset_timer (group
3, tl=0xb5ba4374)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: reset_timer (group
0, tl=0xb5ba4394)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:tm:t_should_relay_response: T_code=0, new_code=200
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:tm:relay_reply:
branch=0, save=0, relay=0
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DBG: trans=0xb5ba4218,
callback type 16, id 0 entered
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:dialog:run_create_callbacks: dialog=0xb5ba1c50, type=128
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: flags=1000
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: get_hdr_body :
content_length=0
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: header field type 13,
name=<Content-Length>, body=<0>
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: found end of header
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:parse_content_type_hdr: missing Content-Typeheader
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers:
flags=ffffffffffffffff
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:dialog:run_create_callbacks: dialog=0xb5ba1c50, type=128
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: Dialog seen REPLY 200 OK
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: old size: 726, new size:
667
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: build_res_from_sip_res:
copied size: orig:75, new: 16, rest: 651 msg= SIP/2.0 200 OK^M Via:
SIP/2.0/UDP 10.110.16.7;branch=z9hG4bK00d9.7030f
716.0^M Via: SIP/2.0/UDP 10.110.1.130;branch=z9hG4bK00d9.9db63ff.0^M Via:
SIP/2.0/UDP 10.111.3.241:5060^M Record-Route:
<sip:10.110.20.1;r2=on;lr;ftag=299341AC-1E61>^M Record-Route: <sip:
10.110.17.8;r2=on;lr;ftag=299341AC-1E61>^M Record-Route:
<sip:10.110.16.7;lr;ftag=299341AC-1E61>^M Record-Route:
<sip:10.110.1.130;r2=on;lr;ftag=299341AC-1E61>^M Record-Route: <sip:10.111
.5.30;r2=on;lr;ftag=299341AC-1E61>^M From:
<sip:4163836062 at 10.111.3.241>;tag=299341AC-1E61^M To:
<sip:4165863543 at 10.111.5.30>;tag=df28^M Call-ID:
C3FBC6C7-2B4C11DC-BE7BCD6C-D251F883 at 10.11
1.3.241^M CSeq: 102 PRACK^M Content-Length: 0^M ^M
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: WARNING:vqm_resize:
resize(0) called
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: put on WAIT
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:
add_to_tail_of_timer[2]: 0xb5ba4260 (64)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:tm:relay_reply: sent
buf=0x81504a8: SIP/2.0 2..., shmem=0xb5ba6328: SIP/2.0 2
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DBG: trans=0xb5ba4218,
callback type 128, id 0 entered
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:dialog:next_state_dlg: dialog 0xb5ba1c50 changed from state 2 to
state 3, due event 3
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:dialog:dlg_onreply:
dialog 0xb5ba1c50 confirmed
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:dialog:insert_tl:
inserting 0xb5ba1c70 for 1859
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:dialog:run_create_callbacks: dialog=0xb5ba1c50, type=4
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers: flags=1000
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]:
DEBUG:parse_content_type_hdr: missing Content-Typeheader
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: parse_headers:
flags=ffffffffffffffff
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: reset_timer (group
3, tl=0xb5ba4374)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: reset_timer (group
0, tl=0xb5ba4394)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG: cleanup_uac_timers:
RETR/FR timers reset
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:tm:UNREF_UNSAFE:
after is 0
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: DEBUG:destroy_avp_list:
destroying list (nil)
Jul 6 12:18:42 rsc1 /usr/sbin/openser[26329]: receive_msg: cleaning up
from dlg_hash.h:
#define DLG_STATE_EARLY 2
#define DLG_STATE_CONFIRMED_NA 3
Also, the DBG probe from dlg_cb.c -> run_dlg_callbacks is missleading. It
should be changed from:
DBG("DEBUG:dialog:run_create_callbacks: dialog=%p, type=%d\n",
to
DBG("DEBUG:dialog:run_dlg_callbacks: dialog=%p, type=%d\n",
regards,
Ovidiu
----------------------------------------------------------------------
Comment By: Bogdan (bogdan_iancu)
Date: 2007-07-06 19:50
Message:
Logged In: YES
user_id=1275325
Originator: NO
Is this happening?? I find it difficult to believe as they are different
transactions....
regards,
Bogdan
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2007-07-06 19:31
Message:
Logged In: YES
user_id=1395524
Originator: YES
But ... there is another problem ... related to this issue (PRACK).
When a 200ok for PRACK is received, the dialog is transitioning from
DLG_STATE_EARLY to DLG_STATE_CONFIRMED_NA. This transition should be
performed only for 200ok for INVITE.
----------------------------------------------------------------------
Comment By: Ovidiu Sas (osas)
Date: 2007-07-06 19:05
Message:
Logged In: YES
user_id=1395524
Originator: YES
Tested ok.
----------------------------------------------------------------------
Comment By: Bogdan (bogdan_iancu)
Date: 2007-07-06 11:31
Message:
Logged In: YES
user_id=1275325
Originator: NO
Hi Ovidiu,
Please try the attached patched and let me know if it fixes the problem -
It's a bit more than a fix as, from script, for PRACK, you can also access
all the dialog related PVs.
regards,
bogdan
File Added: dialog_parck.patch
----------------------------------------------------------------------
Comment By: Bogdan (bogdan_iancu)
Date: 2007-05-30 12:06
Message:
Logged In: YES
user_id=1275325
Originator: NO
yes, indeed, the PRACK wasn't take into consideration. especially it has a
special status. I will take care of it.
bogdan
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1727883&group_id=139143
More information about the Devel
mailing list