repeated message every second "[clock.main:2] We must catchup NN seconds!"

[mailinglists35]

~$ cat rra.soap
rra = input.http("http://89.238.227.6:8004/")
source = mksafe(rra)
output.icecast(%ogg(%opus(bitrate=13, complexity=10, mono)), host="shaincast.caster.fm",
                     port=XXXXX, user="source", password="password", public=false, mount="/listen.mp3",
                     fallible=true,
                     mean(source))

there are sufficient system resources and the process is not using 100% cpu

$ uptime
 06:33:31 up 15 days, 12:57,  1 user,  load average: 0.12, 0.11, 0.04

$ top -b -n 1 -o %CPU| head
top - 06:46:25 up 15 days, 13:10,  1 user,  load average: 0.00, 0.06, 0.06
Tasks:  85 total,   1 running,  84 sleeping,   0 stopped,   0 zombie
%Cpu(s): 12.5 us,  0.0 sy,  0.0 ni, 87.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :    719.2 total,     64.3 free,    298.8 used,    356.1 buff/cache
MiB Swap:    768.0 total,    720.8 free,     47.2 used.    310.9 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 155018 user1     20   0  987644 142584   3040 S   6.2  19.4 113:52.56 liquidsoap
      1 root      20   0  166868   6740   4312 S   0.0   0.9   6:28.69 systemd
      2 root      20   0       0      0      0 S   0.0   0.0   0:00.56 kthreadd

vm guest clock is stable

$ sudo auditctl -l
-a always,exit -F arch=b32 -S settimeofday,adjtimex,clock_settime,clock_adjtime -F key=ADJTIME
-a always,exit -F arch=b64 -S adjtimex,settimeofday,clock_settime,clock_adjtime -F key=ADJTIME
$ sudo ausearch -k ADJTIME --format text | grep ADJTIME|grep -v chrony|wc -l
0

installed from native ubuntu repos in ubuntu 22.04lts (jammy)
ii liquidsoap 2.0.2-1build2 amd64 audio streaming language

liquidsoap output after some time (runs inside screen so I couldn't scroll up enough to see after how much time it started) is filled with these repeating every second:

2022/05/07 06:51:05 [clock.main:2] We must catchup 2.10 seconds!
2022/05/07 06:51:06 [clock.main:2] We must catchup 2.05 seconds!
2022/05/07 06:51:07 [clock.main:2] We must catchup 2.08 seconds!
2022/05/07 06:51:08 [clock.main:2] We must catchup 2.07 seconds!
2022/05/07 06:51:09 [clock.main:2] We must catchup 2.10 seconds!

the resulting stream appears to be working

[TheRealMattLear]

I would recommend increasing the default 5 second buffer on input.http to see if this helps with the issue:

rra = input.http(max_buffer=10., "http://89.238.227.6:8004/")

In addition, i recommend installing the latest stable liquidsoap 2.0.3-1 since 2.0.2 is outdated.

[mailinglists35]

I choose a LTS distro because I want to not maintain it every day :) this comes with cons that I don't always have the latest release available. the pros is that ubuntu 22.04 lts is a very recent release so I can have imho decent versions of packages available. If you provide a repository with prebuilt packages for ubuntu/redhat/fedora, I have no opposition to install them. But compiling from source is not my main pleasure.

I increased the buffer as suggested, however the message kept reappearing. examining logs I can observe the time is linearly increasing over time. process started two weeks ago and has reached yesterday a delay of 60 seconds, at which point it restarted itself:

May 29 05:01:09 racknerd- liquidsoap[182310]: 2022/05/29 05:01:09 [clock.main:2] We must catchup 56.51 seconds!
May 29 05:01:10 racknerd- liquidsoap[182310]: 2022/05/29 05:01:10 [clock.main:2] We must catchup 56.54 seconds!
May 29 05:01:11 racknerd- liquidsoap[182310]: 2022/05/29 05:01:11 [clock.main:2] We must catchup 56.55 seconds!
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [clock.main:2] Too much latency! Resetting active sources...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/24:3] Closing connection...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/24:3] Connecting mount /24 for source@localhost...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/24:3] Connection setup was successful.
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/6:3] Closing connection...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/6:3] Connecting mount /6 for source@localhost...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/6:3] Connection setup was successful.
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/13:3] Closing connection...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/13:3] Connecting mount /13 for source@localhost...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/13:3] Connection setup was successful.
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/listen.mp3:3] Closing connection...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/listen.mp3:3] Connecting mount /listen.mp3 for [email protected]...
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/listen.mp3:2] Connection failed: 403, Mountpoint in use (HTTP/1.0)
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [/listen.mp3:3] Will try again in 3.00 sec.
May 29 05:01:16 racknerd- liquidsoap[182310]: Setting interrupt to true
May 29 05:01:16 racknerd- liquidsoap[182310]: 2022/05/29 05:01:16 [mksafe:3] Switch to safe_blank with forgetful transition.
May 29 05:01:17 racknerd- liquidsoap[182310]: 2022/05/29 05:01:17 [mksafe:3] Switch to input.http_0 with transition.
May 29 05:01:20 racknerd- liquidsoap[182310]: 2022/05/29 05:01:20 [/listen.mp3:3] Connecting mount /listen.mp3 for [email protected]...
May 29 05:01:20 racknerd- liquidsoap[182310]: 2022/05/29 05:01:20 [/listen.mp3:3] Connection setup was successful.
May 30 06:44:18 racknerd- liquidsoap[182310]: 2022/05/30 06:44:18 [clock.main:2] We must catchup 0.15 seconds!
May 30 06:44:22 racknerd- liquidsoap[182310]: 2022/05/30 06:44:22 [clock.main:2] We must catchup 0.56 seconds!

[mailinglists35]

I only noticed now the existence of debs in the release.
Unfortunately none of the debs install in Ubuntu jammy 22.04:

liquidsoap_2.0.5-ubuntu-impish-1_amd64.deb fails with
liquidsoap : Depends: libssl1.1 (>= 1.1.1) but it is not installable

liquidsoap_2.0.5-ubuntu-focal-1_amd64.deb fails with:
liquidsoap : Depends: libfdk-aac1 (>= 0.1.4) but it is not installable
Depends: libsrt1 (>= 1.4.0) but it is not installable
Depends: libssl1.1 (>= 1.1.1) but it is not installable

liquidsoap_2.0.5-debian-buster-1_amd64.deb fails with:
liquidsoap : Depends: libfdk-aac1 (>= 0.1.4) but it is not installable
Depends: libffi6 (>= 3.0.4) but it is not installable
Depends: libjpeg62-turbo (>= 1.3.1) but it is not installable
Depends: libssl1.1 (>= 1.1.1) but it is not installable

liquidsoap_2.0.5-debian-bookworm-1_amd64.deb fails with:
liquidsoap : Depends: libjpeg62-turbo (>= 1.3.1) but it is not installable
Depends: libssl1.1 (>= 1.1.1) but it is not installable

[mailinglists35]

okay, I managed to install with the opam method, a bit inconvenient. will update in a couple of days or weeks if the issue is there. I installed exactly as in the docs plus adding "ffmpeg ogg" to the depext. it shows version 2.0.3-1

this version is more cpu hungry than the one provided by ubuntu. 12% vs 18% cpu with same argument file.

[mailinglists35]

reproduces with opam 2.0.3-1
after less than 48 hours is already at 5 seconds

[vitoyucepi]

@mailinglists35 there are no releases for ubuntu:22.04 yet. The same is for debian:11.

• liquidsoap_2.0.5-ubuntu-impish-1_amd64.deb is for ubuntu:21.10;
• liquidsoap_2.0.5-ubuntu-focal-1_amd64.deb is for ubuntu:20.04;
• liquidsoap_2.0.5-debian-buster-1_amd64.deb is for debian:10;
• liquidsoap_2.0.5-debian-bookworm-1_amd64.deb is for debian:12(testing).

I use docker image based on ubuntu:20.04. So if you're not a big fun of building from source, I recommend using docker images.

[mailinglists35]

anyway I highly doubt 2.0.5 would fix the issue. it would have appeared in changelog, which it does not. not a big fan of docker, neither

[vitoyucepi]

I wonder if

rra = input.http("http://89.238.227.6:8004/")
output.dummy(rra)

will produce the same messages.

[mailinglists35]

I wonder if

rra = input.http("http://89.238.227.6:8004/")
output.dummy(rra)

will produce the same messages.

that alone fails with

Error 7: Invalid value:
That source is fallible

I've started it instead with output.dummy(mksafe(rra))

[mailinglists35]

yep, it does show the message even with the suggested configuration

[vitoyucepi]

Maybe this happens if input state is waiting for new data at that moment.
As stated in the book catchup is caused by insufficient data in upstream.

I think there's a way to monitor stability of your http source.
For example connect to it and calculate data flow and sound length per second.
The correct sound length per second should be exactly 1 without serious fluctuations.
If underflow or overflow will present, then you can increase buffer size.

Also monitor if there any problems with cpu or network on your server.
I've seen vps with poor cpu/net/hdd budget.
If one will try to consume much resources, then iowait/steal will go to 100%.

In generally I recommend to add some kind of monitoring.
Poor man solution will look like a python or bash script that will log

1. system %cpu across different categories;
2. tcp ping time;
3. net send/recv;
4. upstream data flow and produced sound length.

Then you should plot data to see if there any problems at the same time that liquidsoap logs catchup.

[mailinglists35]

I've seen vps with poor cpu/net/hdd budget.

LS logs catchup all the time, every second, starting with the first second until 59th then restarts the stream. I have monitored the vps before and after liquidsoap and even
if it is a budget vps, the kernel time is maintained accurate and system is idle almost 100% when doing nothing

I also started the sample suggestion config on a bare metal machine, will be able shortly to rule out the virtualization as a cause.

[mailinglists35]

anyway, until the results come in, let's assume the source is the root cause.

I don't want any of those messages printed on stdout unless -v is given.

I only expect to see the message "[clock.main:2] Too much latency! Resetting active sources..."

[vitoyucepi]

@mailinglists35 try to monitor upstream. It was my first assumption.

[mailinglists35]

I already am. however the topic of this issue is and always was, "please stop spamming the stdout/stderr with these messages unless -v was given"

[mailinglists35]

the same messages are printed on bare metal, with
liquidsoap -q 'rra = input.http("http://89.238.227.6:8004/"); output.dummy(mksafe(rra))'

since there is no way I can fix the source,

please stop spamming the stdout/stderr with these messages unless -v command line option was given

[mailinglists35]

@toots

[toots]

Hi.

The logs message should stay as this is a serious issue that most people should be made aware of.

As far as I can tell, the issue seems legit is and due to the fact that liquidsoap cannot process the stream in real time, according to the CPU clock.

I imagine that this might be due to the input.http not being able to provide data fast enough, most likely because you are already pulling from another source with real-time constraint but a slightly different clock.

We have a paragraph explaining that in our online doc:

The first reason is external to liquidsoap: there is simply not a unique notion of time in the real world. Your computer has an internal clock which indicates a slightly different time than your watch or another computer’s clock. Moreover, when communicating with a remote computer, network latency causes extra time distortions. Even within a single computer there are several clocks: notably, each soundcard has its own clock, which will tick at a slightly different rate than the main clock of the computer. Since liquidsoap communicates with soundcards and remote computers, it has to take those mismatches into account.

And this should also be covered in the liquidsoap book here: https://www.liquidsoap.info/doc-2.0.4/book.html

If my assumption is correct, you should be able to delegate real-time control to your input.http operator this way:

liquidsoap -q 'rra = input.http(self_sync=true, "http://89.238.227.6:8004/"); output.dummy(mksafe(rra))'

[mailinglists35]

self_sync=true completely suppresses the warning, thank you!

I wish the message would still be there but not as spammy as now.
If you consider is essential, perhaps however could you adjust the emit rate?

Currently it emits one line per second until the catch-up reaches 60 seconds and LS restarts the input.

I imagine it would be less intrusive while still warning the user if instead of using a linear warning, use an exponential backoff timer

this way the same message would still be delivered to user but instead of flooding the output with (3600 seconds x 48 hours) lines it would take only 10-20 lines of log

second 1: We must catchup NN seconds
second 2: We must catchup NN seconds
second 4: Warning: We must catchup NN seconds during the last 2 seconds
second 8: Warning: We must catchup NN seconds during the last 4 seconds
second 16: Warning: We must catchup NN seconds during the last 8 seconds
second 32: Warning: We must catchup NN seconds during the last 16 seconds
second 64: Warning: We must catchup NN seconds during the last 32 seconds
[...]
when catchup is 60 seconds: Too much latency! Resetting active sources...