[BUG] - the expires parameter of the Contact being registered keeps decreasing due to unnecessary dynamic adjustment

[sindy39]

version: opensips 3.4.12 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 6440465a9
main.c compiled on  with gcc 12

Description
When updating/extending an existing registration, the uac_registrant module copies the value of the expires parameter of the Contact URI being re-registered from the expires parameter it has received from the registrar in the latter's 200 response to the previous registration request. If the registrar responds with a value smaller than the requested one, like e.g. Asterisk does, the requested expires value keeps decrementing in the consecutive registration updates.

To Reproduce

1. obtain a pjsip user account on Asterisk (I have noticed this behavior while using Asterisk 16.28.0~dfsg-0+deb11u6) and set maximum_expiration for it to 300 in the aor configuration in pjsip.conf
2. configure a row of table registrant to register with that account, set registrant.expires to 600
3. configure sufficient debug level in opensips.conf or use tcpdump to observe the behavior
4. (re)start opensips and watch the expires value decrease with every registration update

Expected behavior
I could not find any rationale for copying the received expires value to the next request. It is of course necessary to send the registration update request long enough before the expires time received from the registrar elapses, but there is no need to adjust the requested expires value. It would be a different story if the required expires was unacceptably short and the registrar pointed that out using a 423 response.

Relevant System Logs

May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:timer_check: checking ... [1748719396] on htable[0]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:send_register: extra_hdrs=[0x7fb1bb2fe520][82]->[Contact: <sip:249249249@192.168.100.250:50603;transport=UDP>;q=0.813;expires=293
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_uac: next_hop=<sip:192.168.5.240>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:mk_proxy: doing DNS lookup...
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_uac: sending socket is 192.168.5.13
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:print_request_uri: sip:192.168.5.240
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:set_timer: relative timeout is 500000
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb1bb762e40 (1970600000)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb1bb762e70 (1975)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:send_register: result=[1]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt: SIP Reply  (status):
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  version: <SIP/2.0>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  status:  <401>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  reason:  <Unauthorized>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: flags=ffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.5.13>; state=6
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKc6f2.963cafc4.0>; state=16
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via: end of header reached, state=5
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: via found, flags=ffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: this is the first via
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_to_param: tag=z9hG4bKc6f2.963cafc4.0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_to_param: end of header reached, state=13
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:_parse_to: end of header reached, state=29
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:_parse_to: display={}, ruri={sip:249249249@me.cz}
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: <To> [50]; uri=[sip:249249249@me.cz]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: to body [<sip:249249249@me.cz>]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: cseq <CSeq>: <15> <REGISTER>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: content_length=0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: found end of header
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:receive_msg: After parse_msg...
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:forward_reply: found module tm, passing reply to it
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_check: start=0xffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: flags=22
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: hash 12140 label 1291502441 branch 0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fb1bb762c20] after is 1
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: reply matched (T=0x7fb1bb762c20)!
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_check: end=0x7fb1bb762c20
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_should_relay_response: T_code=0, new_code=401
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_pick_branch: picked branch 0, code 401 (prio=500)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=401, flags=2
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:local_reply: branch=0, save=0, winner=0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:local_reply: local transaction completed
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:run_any_trans_callbacks: trans=0x7fb1bb762c20, callback type 256, id 0 entered
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_tm_cback: tm [0x7fb1bb762c20] notification cb for  [401] reply at [1748719396]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record: checking uac=[0x7fb1bb7573d0] state=[1][REGISTERING_STATE] expires=[293] last_register_sent=[1748719396] registration_timeout=[1748719390] auth_user[0x7fb1bb7575dc][9]->[249249249] auth_password=[0x7fb1bb7575e5][9]->[249249249] sock=[0x7fb1bf40bf80] clustering=[/0] enabled=[yes]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:     RURI=[0x7fb1bb7575cb][17]->[sip:192.168.5.240]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:       To=[0x7fb1bb7575b8][19]->[sip:249249249@me.cz]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:     From=[0x7fb1bb7575b8][19]->[sip:249249249@me.cz] tag=[0x7fb1bb7575b3][5]->[4d13a]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:  Call-Id=[0x7fb1bb757598][27]->[61d080fca7d7f7f65eac29816db]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:  Contact=[0x7fb1bb7575ee][49]->[sip:249249249@192.168.100.250:50603;transport=UDP] [0x7fb1bb75761f][8]->[;q=0.813]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_authenticate_body: <realm>="asterisk" state=2
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_authenticate_body: <nonce>="1748719394/82e058bd59388a4dbe7c8280bebadeb0" state=3
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_authenticate_body: <opaque>="4c58aea71a7cfd8c" state=6
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_authenticate_body: <algorithm>="MD5" state=7
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_authenticate_body: <qop>="auth" state=1
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:run_reg_tm_cback: flags=[2] realm=[asterisk] domain=[] nonce=[1748719394/82e058bd59388a4dbe7c8280bebadeb0] opaque=[4c58aea71a7cfd8c] qop=[auth]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_auth:build_authorization_hdr: auth_hdr is <Authorization: Digest username="249249249", realm="asterisk", nonce="1748719394/82e058bd59388a4dbe7c8280bebadeb0", uri="sip:192.168.5.240", opaque="4c58aea71a7cfd8c", qop=auth, nc=00000001, cnonce="3458504348", response="04480eb594c512a16b3860674d4d87f2", algorithm=MD5
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:send_register: extra_hdrs=[0x7fb1bb2fe520][353]->[Contact: <sip:249249249@192.168.100.250:50603;transport=UDP>;q=0.813;expires=293
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_uac: next_hop=<sip:192.168.5.240>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:mk_proxy: doing DNS lookup...
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_uac: sending socket is 192.168.5.13
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:print_request_uri: sip:192.168.5.240
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:set_timer: relative timeout is 500000
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb1bb764bb0 (1970600000)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb1bb764be0 (1975)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:send_register: result=[1]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [2]: 0x7fb1bb762ca0 (1975)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb1bb762c20] after is 0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:destroy_avp_list: destroying list (nil)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:receive_msg: cleaning up
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt: SIP Reply  (status):
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  version: <SIP/2.0>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  status:  <200>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_msg_opt:  reason:  <OK>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: flags=ffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.5.13>; state=6
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK96f2.1f24f566.0>; state=16
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_via: end of header reached, state=5
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: via found, flags=ffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: this is the first via
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_to_param: tag=z9hG4bK96f2.1f24f566.0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_to_param: end of header reached, state=13
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:_parse_to: end of header reached, state=29
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:_parse_to: display={}, ruri={sip:249249249@me.cz}
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: <To> [50]; uri=[sip:249249249@me.cz]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: to body [<sip:249249249@me.cz>]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: cseq <CSeq>: <16> <REGISTER>
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: content_length=0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:get_hdr_field: found end of header
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:receive_msg: After parse_msg...
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:forward_reply: found module tm, passing reply to it
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_check: start=0xffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: flags=22
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: hash 12137 label 1717519089 branch 0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fb1bb764990] after is 1
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_reply_matching: reply matched (T=0x7fb1bb764990)!
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_check: end=0x7fb1bb764990
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:local_reply: branch=0, save=0, winner=0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:local_reply: local transaction completed
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:run_any_trans_callbacks: trans=0x7fb1bb764990, callback type 256, id 0 entered
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_tm_cback: tm [0x7fb1bb764990] notification cb for  [200] reply at [1748719396]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record: checking uac=[0x7fb1bb7573d0] state=[2][AUTHENTICATING_STATE] expires=[293] last_register_sent=[1748719396] registration_timeout=[1748719390] auth_user[0x7fb1bb7575dc][9]->[249249249] auth_password=[0x7fb1bb7575e5][9]->[249249249] sock=[0x7fb1bf40bf80] clustering=[/0] enabled=[yes]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:     RURI=[0x7fb1bb7575cb][17]->[sip:192.168.5.240]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:       To=[0x7fb1bb7575b8][19]->[sip:249249249@me.cz]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:     From=[0x7fb1bb7575b8][19]->[sip:249249249@me.cz] tag=[0x7fb1bb7575b3][5]->[4d13a]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:  Call-Id=[0x7fb1bb757598][27]->[61d080fca7d7f7f65eac29816db]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:uac_registrant:reg_print_record:  Contact=[0x7fb1bb7575ee][49]->[sip:249249249@192.168.100.250:50603;transport=UDP] [0x7fb1bb75761f][8]->[;q=0.813]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_headers: flags=ffffffffffffffff
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_params: Parsing params for:[expires=95]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_params: Parsing params for:[expires=101]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:parse_params: Parsing params for:[expires=292]
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:insert_timer_unsafe: [2]: 0x7fb1bb764a10 (1975)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb1bb764990] after is 0
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:destroy_avp_list: destroying list (nil)
May 31 21:23:16 opensips-bookworm /usr/sbin/opensips[540]: DBG:core:receive_msg: cleaning up

OS/environment information

• Operating System: Debian 12
• OpenSIPS installation: debs
• other relevant information: Asterisk 16.28.0~dfsg-0+deb11u6, pjsip

[sindy39]

Until it eventually gets resolved, this is an ugly workaround:

local_route {
        if (is_method("REGISTER")) {
                $var(newExpires) = $(ct.fields(expires){s.int}) + 10;
                $var(newContact) = "<" + $ct.fields(uri) + ">;q=" + $ct.fields(q) + ";expires=" + $var(newExpires);
                if (remove_hf("Contact")) {
                        insert_hf("Contact: $var(newContact)\r\n");
                }
        }
}

There unfortunately seems to be no way to access the registrant table from within the script to fetch the expiry value - at least if db_text is used, as it does not support the generic avp_db_query() from avpops whilst all the other methods depend on a fixed structure of the table being accessed.

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[github-actions]

Marking as closed due to lack of progress for more than 30 days. If this issue is still relevant, please re-open it with additional details.

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[bogdan-iancu]

Hi @sindy39 , the reason for re-seeding the expires of the registrant records with the received expires (from 200 ok) is simple - just to avoid using 2 variables, the requested_expires and granted_expires.....
But I see your case, it makes sense - would you be able to test a patch here ?