[BUG] timer task <b2bl-clean> already scheduled * ms ago (now * ms), delaying execution

[devoxy1]

Hello!

We experience an issue when opensips hangs and stops responding from time to time with error message of timer_tiker. I'm not sure what's causing this and how to debug the issue.

OpenSIPS version you are running

version: opensips 3.4.0 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, CC_O0, 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: e42a648ff
main.c compiled on 16:02:17 Jul 26 2023 with gcc 9

Describe the bug
At some point opensips starts to throw messages about timer task and stops responding to any SIP messages. Only restart helps to fix the issue.

To Reproduce

Expected behavior
Opensips doesn't hang.

Relevant System Logs

opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 82590 ms ago (now 143230 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 83580 ms ago (now 144220 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 87270 ms ago (now 147910 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 87270 ms ago (now 147910 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 87270 ms ago (now 147910 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 87470 ms ago (now 148110 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 88470 ms ago (now 149110 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 89470 ms ago (now 150110 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 90470 ms ago (now 151110 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 91460 ms ago (now 152100 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 92440 ms ago (now 153080 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 93430 ms ago (now 154070 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 94470 ms ago (now 155110 ms), delaying execution
opensips[163016]: WARNING:core:timer_ticker: timer task <b2bl-clean> already scheduled 95430 ms ago (now 156070 ms), delaying execution

OS/environment information

• Operating System: Ubuntu 20.04.5 LTS
• OpenSIPS installation: git
• other relevant information:

Additional context
I get trap during this issue. gdb file can be found here: https://file.io/X5a3PDFKWNPt

[devoxy1]

I think i was able to reproduce the issue and there is actually segfault happening.
My scenario is:
A calls B via opensips instance with b2b setup and "refer" scenario. Once call is answered A transfers B to C via REFER.
I have REFER catch in script and generating new INVITE:

xlog("L_INFO", "[$ci] [$rm] [B2B_LOGIC_REQUEST] BLIND TRANSFER - Refer-To: $hdr(Refer-To)");
xlog("L_INFO", "[$ci] [$rm] [B2B_LOGIC_REQUEST] Refer-To: $hdr(Refer-To)");
$var(uri_transform)=$(hdr(Refer-To){nameaddr.uri});
$var(refer-to)=$(var(uri_transform){s.select,0,?});

b2b_client_new("referee", $var(refer-to),,,, $avp(b2b_hdrs), $avp(b2b_hdr_bodies));
$rtp_relay = "replace-origin replace-session-connection";
$rtp_relay_peer = "replace-origin replace-session-connection";
rtp_relay_engage("rtpengine");

# bridge the referrer's peer with the referee
b2b_bridge("peer", "referee",,"notify,no-late-sdp");

Once REFER is sent opensips generates log with SDP error:

opensips[165080]: ERROR:b2b_logic:bridging_start_new_ent: SDP not found
opensips[165080]: ERROR:b2b_logic:b2bl_bridge: Failed to start bridging with new entity
opensips[165080]: ERROR:b2b_logic:b2b_script_bridge: Failed to process bridge action
opensips[165081]: ERROR:b2b_logic:b2b_add_dlginfo: No b2b_key match found
opensips[165081]: ERROR:b2b_entities:b2b_tm_cback: Failed to add dialoginfo

I use flag no-late-sdp in bridge function so SDP is composed in first INVITE for transfer instead of ACK which is default behavior, but new INVITE is sent out without SDP which is incorrect behavior, which causes the error and then causes segfault. After that opensips stops responding and throws errors:
opensips[165079]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 4970 ms ago (now 108400 ms), delaying execution until restart.
If i remove no-late-sdp flag than there is no error, transfer works and opensips doesn't hang.

I'm also attaching bt full from core file and corresponding opensips log: https://file.io/FbNIeVL6qATZ

[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.

[devoxy1]

Up

[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.

[devoxy1]

Still actual

[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.

[devoxy1]

Up

[devoxy1]

I think this might be related to this bug #3195
I've updated to the latest version 3.4, made some tests and didn't experience the issue so far. Will monitor some more time and revert back.

[bogdan-iancu]

Hi @devoxy1, thanks for your report and sorry for the slow reply here. First of all, be sure you are using the latest (from GIT repo) sources of 3.4 branch - there were several fixes there. If the crash still persists, please upload the backtrace again (maybe use pastebin to avoid the fast expiring of your uploads).

[devoxy1]

Hi @bogdan-iancu!

There was no crash but more of a deadlock. Opensips process kept running but didn't reply to any requests and log was filled with "timer task" messages. Anyways it seems like the issue is resolved with latest version 3.4.1, git revision: c03bbc4

I will re-open new report if the issue comes up again. Thank you!

[bogdan-iancu]

Thanks @devoxy1 for the update, let's do that. For now I will close here.