[reSIProcate] Incomplete processing of subscription expires values by DUM
Hello all.
I have encountered a problem with the way DUM is dealing with subscription
expiry values.
The problem occurs when a device does not include the ";expires=..."
parameter on the Subscription-State: header in the NOTIFY messages. In this
situation DUM is not refreshing the subscription before it expires as it is
using a default expiry value of 3600 seconds (verified by turning on full
debug).
Now looking at the code it looks like it should be using the value from
the last request (ClientSubscription::processNextNotify) if the parameter
is not present (although this behaviour is not really correct--see below).
But for some reason it is not seeing the Expires: header in the last
request (and yes it is present in the SUBSCRIBE message that goes out--see
debug trace (and also verified by Ethernet trace)). So it is defaulting to
a value of 3600.
Looking at the debug trace (included below) you can see the Expires:
header in the last request but right below it the header does not appear in
the new request it is building for some reason. So when it gets to the test
it does not see the header and defaults to 3600.
Now even if it did take the value from the last request, technically this
would not be correct. As per RFC 3265, the notifier can modify the
requested expiry value by making it lower. This would be indicated in the
Expires: header in the 200 OK sent back. But DUM ignores the 200 OK of a
SUBSCRIBE and waits for the first NOTIFY which is sort of correct as the
subscription is to be considered in the neutral state unit it is received.
But it needs to look at the Expires: header value in the 200 OK. What if a
SUBSCRIBE is sent without an Expires: header at all (which is valid). The
notifier would then report the value being used (default of the event
package) in the 200 OK. And if it does not use the ";expires=..." parameter
on the Subscription-State: header of the NOTIFY (which is valid as it is a
SHOULD not a MUST in RFC 3265) then DUM would have no idea what is actually
being used by ignoring the value in the 200 OK.
So is there someone who is familiar with this section of code? Tomorrow I
will be digging into the first problem of the expiry value not being found
in the last request as a temporary fix (although any pointers would be
welcome :-) I am guessing that the bigger problem of correctly using the
value from the 200 OK is going to take far greater investigation.
Thanks.
[RESIP:DUM] Dialog::dispatch: SipReq: NOTIFY sipif@xxxxxxxxxxxxx:5060
tid=-541ba0c40bb2e6bb6f8426f87b7c6051 cseq=NOTIFY
contact=snom320@xxxxxxxxxxxxx:2051 / 1 from(wire)
[RESIP:DUM] Making subscription (from creator) request: SUBSCRIBE
sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx SIP/2.0
>Via: SIP/2.0/ ;branch=z9hG4bK-d87543-d165ab066803f961-1--d87543-;rport
>Max-Forwards: 70
>Contact: <sip:sipif>
>To: <sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx>
>From: <sip:sipif@xxxxxxxxxxxxxxxxx>;tag=3827ae13
>Call-ID: db1a5c02396f0752Y2IzMzFhMTkzYThjOWE3M2NkYjE4NDAyOWM4YTg4YzU.
>CSeq: 1 SUBSCRIBE
>Expires: 200
>Allow: NOTIFY
>User-Agent: SIPIF/0.1
>Event: dialog
>Content-Length: 0
[RESIP:DUM] ClientSubscription::ClientSubscription from SipReq: SUBSCRIBE
snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx tid=d165ab066803f961 cseq=SUBSCRIBE
contact=sipif / 1 from(tu)
[RESIP:DUM] Dialog::makeRequest: SUBSCRIBE
sip:snom320@xxxxxxxxxxxxx:2051;line=n3b3x9av SIP/2.0
>Via: SIP/2.0/ ;branch=z9hG4bK-d87543-f1145b757938512d-1--d87543-;rport
>Max-Forwards: 70
>Route:
<sip:192.168.1.96:5080;lr;a;t=3827ae13;s=3af5bb44dabbb05888df09155ce9a1ae>
>Contact: <sip:sipif>
>To: <sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx>;tag=wikel513dl
>From: <sip:sipif@xxxxxxxxxxxxxxxxx>;tag=3827ae13
>Call-ID: db1a5c02396f0752Y2IzMzFhMTkzYThjOWE3M2NkYjE4NDAyOWM4YTg4YzU.
>CSeq: 2 SUBSCRIBE
>Event: dialog
>Content-Length: 0
[RESIP:DUM] [ClientSubscription]
<sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx>;tag=wikel513dl
Subscriptions::onNewSubscription
Subscriptions::convertHandleToSubscription Client Subscription Handle :
(6:01895CD8)
... AppDialogSet Handle : (4:0188A9B0)
... typeid *AppDialogSet().get() 'class sipapi::Subscription'
... Subscription : 'sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx'
Subscription::setActive 'sip:snom320@xxxxxxxxxxxxxxxxxxxxxxxxxxx'
Subscription Status callback. Id:2 'Subscribed' (0)
[RESIP:DUM] no queued notify
[RESIP:DUM] No expires header in last request, set to 3600