[OpenSIPS-Users] var/avp persistence, onreply_route, and script context

Bobby Smith bobby.smith at gmail.com
Mon Aug 8 22:58:29 CEST 2011 

Hi Razvan,

So in trying to do this from the logs, I think that the dialog matching
doesn't actually happen until the onreply_route processing is finished, so I
cant access either the dlg_val or the DLG_flags.  Log is below.

I should mention this is from the 1.6.4 branch of opensips (not current
1.7).


My default route looks like this:

route {
     create_dialog();
     xlog("[REQUEST $ci] :: create dialog for $rm $ru placed in status
$DLG_status with return code $rc");
     ...
      loose_route();
      xlog("[REQUEST $ci] :: $rm $ru :: PRINT INFORMATION ABOUT DIALOG :::
dialog status $DLG_status, dialog flags $DLG_flags, dlg_val(cisco)
$dlg_val(cisco)");
     ...
}

and my onreply looks like this:

onreply_route {
     xlog("[RESPONSE $ci] :: $rs :: PRINTING DIALOG INFO :: dialog status
$DLG_status, dialog flags $DLG_flags, dlg_val(cisco) $dlg_val(cisco)");
      $dlg_val(cisco) = "true";
      set_dlg_flag("3");
     ...
}

And here's the log statements from this occurring:

%011-08-08T20:39:30.574404+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_msg: SIP Reply
 (status):
2011-08-08T20:39:30.574478+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_msg:  version:
<SIP/2.0>
2011-08-08T20:39:30.574498+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_msg:  status:
 <200>
2011-08-08T20:39:30.574513+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_msg:  reason:  <OK>
2011-08-08T20:39:30.574529+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: flags=2
2011-08-08T20:39:30.574542+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_to_param:
tag=25ac01ebd3e5cd73i3
2011-08-08T20:39:30.574558+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_to: end of header
reached, state=29
2011-08-08T20:39:30.574573+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_to: display={},
ruri={sip:TEST107751 at sip.foo.com}
2011-08-08T20:39:30.574587+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:get_hdr_field: <To> [67];
uri=[sip:TEST107751 at sip.foo.com]
2011-08-08T20:39:30.574600+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:get_hdr_field: to body [<
sip:TEST107751 at sip.foo.com>]
2011-08-08T20:39:30.574612+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:get_hdr_field: cseq
<CSeq>: <1> <INVITE>
2011-08-08T20:39:30.574629+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via_param: found
param type 232, <branch> = <z9hG4bK8d7f.61ce6675.0>; state=16
2011-08-08T20:39:30.574646+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via: end of header
reached, state=5
2011-08-08T20:39:30.574661+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: via found,
flags=2
2011-08-08T20:39:30.574674+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: this is
the first via
2011-08-08T20:39:30.574688+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:receive_msg: After
parse_msg...
2011-08-08T20:39:30.574705+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: [RESPONSE
1710098c6f37dc00e42e5d0d210ed870 at 10.2.1.87] :: 200 :: PRINTING DIALOG INFO
:: dialog status <null>, dialog flags <null>, dlg_val(cisco)
2011-08-08T20:39:30.574720+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: ERROR:core:do_assign: setting PV
failed
2011-08-08T20:39:30.574734+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: ERROR:core:do_assign: error at
line: 678
2011-08-08T20:39:30.574751+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: [RESPONSE
1710098c6f37dc00e42e5d0d210ed870 at 10.2.1.87] :: setting dlg_val(cisco) to
 with DLG_flags = <null>
2011-08-08T20:39:30.574769+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers:
flags=ffffffffffffffff
2011-08-08T20:39:30.574784+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via_param: found
param type 235, <rport> = <5060>; state=6
2011-08-08T20:39:30.574801+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via_param: found
param type 234, <received> = <4.2.2.170>; state=6
2011-08-08T20:39:30.574818+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via_param: found
param type 232, <branch> = <z9hG4bK8d7f.78413d97.0>; state=16
2011-08-08T20:39:30.574833+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via: end of header
reached, state=5
2011-08-08T20:39:30.574847+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: via found,
flags=ffffffffffffffff
2011-08-08T20:39:30.574862+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers:
parse_headers: this is the second via
2011-08-08T20:39:30.574876+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via_param: found
param type 232, <branch> = <z9hG4bK4360341242842074756251312835968830>;
state=16
2011-08-08T20:39:30.574893+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_via: end of header
reached, state=5
2011-08-08T20:39:30.574909+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: via found,
flags=ffffffffffffffff
2011-08-08T20:39:30.574923+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:get_hdr_field:
content_length=208
2011-08-08T20:39:30.574936+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:get_hdr_field: found end
of header
2011-08-08T20:39:30.574989+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:check_ip_address: params
192.168.30.194, 4.2.2.171, 0
2011-08-08T20:39:30.575009+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers:
flags=ffffffffffffffff
2011-08-08T20:39:30.575034+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:nathelper:check_content_type:
type <application/sdp> found valid
2011-08-08T20:39:30.575071+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:forward_reply: found
module tm, passing reply to it
2011-08-08T20:39:30.575088+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_check:
start=0xffffffffffffffff
2011-08-08T20:39:30.575105+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: flags=22
2011-08-08T20:39:30.575132+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: flags=8
2011-08-08T20:39:30.575149+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_reply_matching: hash
63448 label 1466362902 branch 0
2011-08-08T20:39:30.575172+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
2011-08-08T20:39:30.575190+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_reply_matching: reply
matched (T=0x2b6e1e77db78)!
2011-08-08T20:39:30.575217+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers: flags=8
2011-08-08T20:39:30.575232+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_check: end=0x2b6e1e77db78
2011-08-08T20:39:30.575250+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:reply_received: org. status
uas=180, uac[0]=180 local=0 is_invite=1)
2011-08-08T20:39:30.575273+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:t_should_relay_response:
T_code=180, new_code=200
2011-08-08T20:39:30.575296+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:relay_reply: branch=0,
save=0, relay=0
2011-08-08T20:39:30.575311+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:run_trans_callbacks:
trans=0x2b6e1e77db78, callback type 16, id 0 entered
2011-08-08T20:39:30.575334+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:push_reply_in_dialog:
0x2b6e1e77ced0 totag in rpl is <25ac01ebd3e5cd73i3> (18)
2011-08-08T20:39:30.575350+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:push_reply_in_dialog:
branch with tag <25ac01ebd3e5cd73i3> already exists
2011-08-08T20:39:30.575374+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:parse_headers:
flags=ffffffffffffffff
2011-08-08T20:39:30.575397+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: current rr
is <sip:4.2.2.171;lr=on;nat=yes;did=1a7.ed2a0657>
2011-08-08T20:39:30.575420+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: current rr
is <sip:4.2.2.170;r2=on;lr=on;did=1a7.719de5a3>
2011-08-08T20:39:30.575443+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: current rr
is <sip:172.16.30.170;r2=on;lr=on;did=1a7.719de5a3>
2011-08-08T20:39:30.575459+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: skipping 3
route records
2011-08-08T20:39:30.575474+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: out rr []
2011-08-08T20:39:30.575501+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:core:print_rr_body: we have 3
records
2011-08-08T20:39:30.575524+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:dlg_update_routing:
dialog 0x2b6e1e77ced0[1]: rr=<> contact=<sip:TEST107751 at 192.168.30.194:5063>
2011-08-08T20:39:30.575557+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]:
DBG:core:build_res_buf_from_sip_res:  old size: 1096, new size: 1033
2011-08-08T20:39:30.575611+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]:
DBG:core:build_res_buf_from_sip_res: copied size: orig:717, new: 654, rest:
379 msg=#012SIP/2.0 200 OK#015#012To:
<sip:TEST107751 at sip.foo.com>;tag=25ac01ebd3e5cd73i3#015#012From:
"Bobby Smith" <sip:507 at 10.2.1.87>;tag=6174017421312835968828#015#012Call-ID:
1710098c6f37dc00e42e5d0d210ed870 at 10.2.1.87#015#012CSeq: 1 INVITE#015#012Via:
SIP/2.0/UDP
4.2.2.170;rport=5060;received=4.2.2.170;branch=z9hG4bK8d7f.78413d97.0#015#012Via:
SIP/2.0/UDP 10.2.1.87:5060;branch=z9hG4bK4360341242842074756251312835968830#015#012Record-Route:
<sip:4.2.2.171;lr=on;nat=yes;did=1a7.ed2a0657>#015#012Record-Route:
<sip:4.2.2.170;r2=on;lr=on;did=1a7.719de5a3>#015#012Record-Route:
<sip:172.16.30.170;r2=on;lr=on;did=1a7.719de5a3>#015#012Contact: "Extension"
<sip:TEST107751 at 192.168.30.194:5063>#015#012Server:
Linksys/SPA942-5.2.8#015#012Content-Length: 208#015#012Allow: ACK, BYE,
CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER#015#012Supported:
replaces#015#012Content-Type: application/sdp#015#012#015#012v=0#015#012o=-
11235 11235 IN IP4 192.168.30.194#015#012s=-#015#012c=IN IP4
192.168.30.194#015#012t=0 0#015#012m=audio 16466 RTP/AVP 0
101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101
telephone-event/8000#015#012a=fmtp:101
0-15#015#012a=ptime:30#015#012a=sendrecv#015#012
2011-08-08T20:39:30.575655+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:update_totag_set: new
totag
2011-08-08T20:39:30.575669+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:insert_timer_unsafe: [2]:
0x2b6e1e77dbf8 (136)
2011-08-08T20:39:30.575687+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:tm:run_trans_callbacks:
trans=0x2b6e1e77db78, callback type 128, id 0 entered
2011-08-08T20:39:30.575702+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:next_state_dlg: dialog
0x2b6e1e77ced0 changed from state 2 to state 3, due event 3
2011-08-08T20:39:30.575717+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:dlg_onreply: dialog
0x2b6e1e77ced0 confirmed
2011-08-08T20:39:30.575741+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]:
DBG:dialog:insert_dlg_timer_unsafe: inserting 0x2b6e1e77cf08 for 43331
2011-08-08T20:39:30.575757+00:00 atlsvsreg02
/usr/local/opensips/sbin/opensips[28194]: DBG:dialog:ref_dlg: ref dlg
0x2b6e1e77ced0 with 1 -> 3


On Fri, Aug 5, 2011 at 3:53 AM, Razvan Crainea
<razvancrainea at opensips.org>wrote:

> **
> Hi Bobby,
>
> The $DLG_flags or a $dlg_var(name) are the pseudo variables that should
> help you. In order to use them, you must use create_dialog() [1] for the
> Initial INVITE.
> In the sequential requests, you should read the values only after
> loose_route() [2] is called, because there's where the dialog is matched.
> Please try again and let us know your results.
>
> [1] http://www.opensips.org/html/docs/modules/devel/dialog.html#id293854
> [2] http://www.opensips.org/html/docs/modules/devel/rr.html#loose-route-id
>
> Regards,
>
> Razvan Crainea
> OpenSIPS Developer
>
>
> On 05.08.2011 07:14, Bobby Smith wrote:
>
> Thanks for the suggestion -- unfortunately I saw this previously in a
> thread and thought that'd be the key, but the results from cranking debug up
> the same show it to be a different transaction on receiving the ACK and thus
> the value is null. :(
>
>  I've played around with this just a little bit more and by modifying the
> localcache key to be $fU_$ci (from user / callid pair, or some tag, or
> something related to the initial request that's available in the script
> context) I can get it to work how I want, but this really just doesn't seem
> like the right way to do it.
>
>
> On Fri, Aug 5, 2011 at 12:08 AM, Brett Nemeroff <brett at nemeroff.com>wrote:
>
>>  See if setting this param on helps.
>>
>> http://www.opensips.org/html/docs/modules/devel/tm.html#id293118
>> -Brett
>>
>> On Aug 4, 2011, at 7:48 PM, Bobby Smith <bobby.smith at gmail.com> wrote:
>>
>>  All,
>>
>> Here's why I'm trying to accomplish:
>>
>>  route [subsequent_request] {
>>    if (has_totag && is_method("ACK") {
>>      if (MY_VAR = "cisco") {
>>         lookup("location");
>>         ... relay and exit
>>      }
>>      else {
>>           ... relay and exit lr
>>      }
>>    }
>> }
>>
>>  onreply_route [foo] {
>>      ....
>>      if($ua =~ "Cisco-CP79") {
>>           MY_VAR = "cisco"
>>      }
>> }
>>
>>  The reasons are not really relevant (it's to get rid of a really poor UA
>> implementation on older Cisco 79XX firmwares), but my intent is:
>>
>>  1) Set a transaction-visible-only value in onreply_route [foo]
>> 2) Retrieve it on the ACK that completes the initial invite transaction.
>>
>> My problems:
>>
>>  1) if MY_VAR is an $avp, it returns null on retrieving it in the
>> route[subsequent_request], even with the onreply flag for tm set.
>> 2) if MY_VAR is a $var, it's process global and so, the next transaction
>> that comes in could share the same state (race)
>> 3) if MY_VAR is a flag, I can't retrieve it in the route [subsequent
>> request]
>> 4) if MY_VAR is a dlg_flag or a dlg_var, I can't retrieve it in the
>> subsequent request even if invoking create_dialog as the first action in the
>> routing script (if it's an initial invite).
>> 5) The only thing I've been able to do is create a unique key via
>> localcache (with $fU_useragent = myvalue) and fetch it, but this does not
>> allow multiple UA's to register with the same fU
>>
>>  My question is, is there any way to set a transaction state only value
>> in an onreply hook, and retrieve it on the ACK?
>>
>> I know according to the RFC:
>>
>>        The reason for this separation is rooted in the importance <http://rfc-ref.org/RFC-TEXTS/3261/kw-importance.html> of
>>       delivering all 200 (OK) responses to an INVITE <http://rfc-ref.org/RFC-TEXTS/3261/kw-invite.html> to the UAC <http://rfc-ref.org/RFC-TEXTS/3261/kw-uac.html>.  To
>>       deliver them all to the UAC <http://rfc-ref.org/RFC-TEXTS/3261/kw-uac.html>, the UAS <http://rfc-ref.org/RFC-TEXTS/3261/kw-uas.html> alone takes responsibility
>>
>>       for retransmitting them (see Section 13.3.1.4), and the UAC <http://rfc-ref.org/RFC-TEXTS/3261/kw-uac.html> alone
>>       takes responsibility for acknowledging them with ACK <http://rfc-ref.org/RFC-TEXTS/3261/kw-ack.html> (see Section
>>       13.2.2.4).  Since this ACK <http://rfc-ref.org/RFC-TEXTS/3261/kw-ack.html> is retransmitted only by the UAC <http://rfc-ref.org/RFC-TEXTS/3261/kw-uac.html>, it is
>>       effectively considered its own transaction <http://rfc-ref.org/RFC-TEXTS/3261/kw-transaction.html>.
>>
>>
>>
>>  Is there a way to get this associated with the right dialog or
>> something?  I've tried setting a dialog profile on initial invite, storing a
>> value in the 200 OK onreply, and retrieving it as well in the ACK, but I get
>> no dialog has been created (I guess because the dialog is early or
>> something).
>>
>>
>> Thanks for the ideas,
>>
>> BobbyS
>>
>>   _______________________________________________
>> Users mailing list
>> Users at lists.opensips.org
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users at lists.opensips.org
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>
> _______________________________________________
> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20110808/e48815cc/attachment-0001.htm>

More information about the Users mailing list