Regression in v0.643 - no socket found to match Record Route
Closed this issue · 9 comments
It appears the acknowledgement packet from dSIPRouter to Microsoft Teams Direct Routing is not being sent when an inbound call to Microsoft Teams is accepted in v0.643 on a clean Debian 10 install of v0.643. The recipient of the call sees a timer stuck at 00:00 (zero minutes and zero seconds) despite being able to converse with the person that called them, but the call then drops 29 seconds after being answered.
This issue does not affect inbound calling on v0.63 on Debian 9 based on my testing.
Below are the concerning log lines (specifically the WARNING: rr parts):
Feb 11 12:24:18 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:36 sbc3 /usr/sbin/kamailio[8545]: ERROR: <core> [core/msg_translator.c:3318]: sip_msg_apply_changes(): cannot apply msg changes after adding record-route header - it breaks conditional 2nd header
Feb 11 12:24:36 sbc3 /usr/sbin/kamailio[8545]: ERROR: rr [rr_mod.c:350]: w_record_route(): Double attempt to record-route
Feb 11 12:24:36 sbc3 /usr/sbin/kamailio[8545]: ERROR: htable [ht_dmq.c:228]: ht_dmq_send(): ht_dmq_peer is null!
Feb 11 12:24:36 sbc3 /usr/sbin/kamailio[8545]: ERROR: htable [ht_var.c:121]: pv_set_ht_cell(): dmq relication failed
Feb 11 12:24:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:49 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:49 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:49 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:49 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:55 sbc3 /usr/sbin/kamailio[8559]: NOTICE: acc [acc.c:279]: acc_log_request(): ACC: transaction answered: timestamp=1644611095;method=INVITE;from_tag=Zy9cB7p5S101B;to_tag=7eff5cf9ba4a476aa7bebef7d78$
Feb 11 12:24:55 sbc3 /usr/sbin/kamailio[8545]: WARNING: rr [loose.c:772]: rr_do_force_send_socket(): no socket found to match second RR (sip:acceleratenetworks.sbc3.callpipe.com:5061;transport=tls;r2=on;lr)
Feb 11 12:24:59 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:59 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:24:59 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:24:59 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:08 sbc3 /usr/sbin/kamailio[8545]: WARNING: rr [loose.c:772]: rr_do_force_send_socket(): no socket found to match second RR (sip:acceleratenetworks.sbc3.callpipe.com:5061;transport=tls;r2=on;lr)
Feb 11 12:25:09 sbc3 /usr/sbin/kamailio[8545]: WARNING: rr [loose.c:772]: rr_do_force_send_socket(): no socket found to match second RR (sip:acceleratenetworks.sbc3.callpipe.com:5061;transport=tls;r2=on;lr)
Feb 11 12:25:09 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:09 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:09 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:09 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:10 sbc3 /usr/sbin/kamailio[8545]: WARNING: rr [loose.c:772]: rr_do_force_send_socket(): no socket found to match second RR (sip:acceleratenetworks.sbc3.callpipe.com:5061;transport=tls;r2=on;lr)
Feb 11 12:25:12 sbc3 /usr/sbin/kamailio[8559]: NOTICE: acc [acc.c:279]: acc_log_request(): ACC: transaction answered: timestamp=1644611112;method=BYE;from_tag=Zy9cB7p5S101B;to_tag=7eff5cf9ba4a476aa7bebef7d78f83$
Feb 11 12:25:12 sbc3 /usr/sbin/kamailio[8545]: WARNING: rr [loose.c:772]: rr_do_force_send_socket(): no socket found to match second RR (sip:acceleratenetworks.sbc3.callpipe.com:5061;transport=tls;r2=on;lr)
Feb 11 12:25:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:19 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:25 sbc3 /usr/sbin/kamailio[8545]: NOTICE: acc [acc.c:279]: acc_log_request(): ACC: transaction answered: timestamp=1644611125;method=BYE;from_tag=7eff5cf9ba4a476aa7bebef7d78f83cd;to_tag=Zy9cB7p5S10$
Feb 11 12:25:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:29 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Feb 11 12:25:39 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:404]: lval_assign(): assignment failed at pos: (824,15-824,36)
Feb 11 12:25:49 sbc3 /usr/sbin/kamailio[8559]: ERROR: <core> [core/lvalue.c:346]: lval_pvar_assign(): non existing right pvar
Thanks Dan! Just chiming in to confirm that I worked with you hands-on and we confirmed this issue together. Appears to be a regression 0.63 => 0.643
Impacts Teams PSTNHub routing in the form of calls dropping after a time, and call timers will stall at zero at call start.
Hi @QuinnEbert,
I have not tested or worked with v0.642, only v0.643 has been tested and shown this issue for me.
@danry25 typo, apologies! Updated my note!
@danry25 just confirmed that release 0.643 isn't yet certified for Teams direct routing support, we advise Teams direct routing users to stick with 0.642 for now, 0.643 is still a work in progress and the certification items will be resolved before the 0.643 release series is completed
Note to self: To get v0.643 to install on Debian 10 I had to:
- Update dsiprouter.sh to export RTPENGINE_VER="10.1.1.1"
- apt install tmux htop git curl libffi-dev python3-pip
Thanks Dan!
I have not personally seen troubles on Deb10 previously without specifying RTPENGINE_VER in the script...
I know tmux and htop are in my top 5 "nice to haves" -- did you see install failures without git / curl / python3-pip and without specifying RTPENGINE_VER on Debian 10, and if so, can you extrapolate on those failures with some context?
Note to myself: spend more time with 0.643/Deb10 in the lab...
Hi Quinn,
Only libffi-dev and python3-pip appear to be needed on Debian 10, the rest pf those packages are nice to have but not essential.
Looking to close this issue out, @mackhendricks the fix you wrote on commit 74b38a9 works for me when manually applied to v0.642 but needs to be backported to the affected git branches (at least v0.642 and v0.643).
Could I encourage a dOpenSource team member to backport this to the affected branches and close this issue out perchance?
We will backport this to v0.642 and v0.643 within the next day