irqbalance loop of blank messages

RE: https://bugs.launchpad.net/ubuntu/+source/ubuntu-meta/+bug/1833322

That, back in 2019, recommended that irqbalance be removed as default installed.

RE: https://launchpad.net/debian/+source/irqbalance/+changelog
>>>
mafoelffen@debina11:~$ apt list irqbalance list -a
Listing... Done
irqbance/oldstable 1.7.0-1 amd64

mafoelffen@debian11:$ lsb_release -d
Description: Deian GNU/Linux 11 (bullseye)
>>>

Other distro's (RedHat, Debian, PopOS) and more than one package from the Ubuntu Repo's (Valve Steam, CpuFreq) currently recommend removing irqbalance, if installed. And do not have it installed by default = is an optional manual install.
RE:
https://github.com/ValveSoftware/Proton/issues/3243
http://konkor.github.io/cpufreq/faq/

Why is this still installed in the Noble Repo's as a default install?

Status changed to 'Confirmed' because the bug affects multiple users.

Thank you Mike, I'll chime in on bug 1833322 in regard to reconsider it being default enabled.

Now back to this - in regard to the report here which is the more technical "the log is flooded by these messages".
I've looked at this at a few machines I had (I admit, mostly virtual ones where irqbalance isn't doing too much) and it is indeed easy to reproduce.

# Get a clean test system (needs more than 1 cpu or it will exit early):
$ lxc launch ubuntu-minimal-daily:n n-vm --ephemeral --vm -c limits.cpu=4 -c limits.memory=2GiB
$ lxc exec n-vm bash

# Install
# it is BTW no more default installed on cloud images :-)
$ apt install irqbalance

# Check log
$ journalctl -u irqbalance
root@n-vm:~# journalctl -u irqbalance
Jan 05 12:09:40 n-vm systemd[1]: Started irqbalance.service - irqbalance daemon.
Jan 05 12:09:40 n-vm irqbalance[987]: Prevent irq assignment to these isolated CPUs: 00000000
Jan 05 12:09:40 n-vm irqbalance[987]: Prevent irq assignment to these adaptive-ticks CPUs: 00000000
Jan 05 12:09:40 n-vm irqbalance[987]: Banned CPUs: 00000000
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 66 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 65 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 64 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 55 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 58 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 56 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 59 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 57 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 26 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 53 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 54 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 35 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 38 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 36 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 37 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 24 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 48 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 49 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 21 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 31 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 29 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 63 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 61 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 62 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 10 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 27 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 33 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 34 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 25 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 51 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 60 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 45 to database
Jan 05 12:09:40 n-vm irqbalance[987]: Adding IRQ 43 to database
Jan 05 12:09:40 n-vm irqbalan...

Hmm,
when it enters the main loop it initializes a timed check to cope with e.g. changing topology and hotplug.

constants.h:5:#define SLEEP_INTERVAL 10
...
g_timeout_add_seconds(sleep_interval, scan, NULL);

And that function starts like:
 gboolean scan(gpointer data __attribute__((unused)))
 {
     log(TO_CONSOLE, LOG_INFO, "\n\n\n-----------------------------------------------------------------------------\n");

So I guess we know what emits those, the question is why wasn't this seen before.
Because the code to emit that is in former Ubuntu releases, something else must have changed the behavior.

Turns out the actual new behavior is in the logging.

The old was ultra-silent

Mantic:
root@m-vm:~# journalctl -u irqbalance -f
Jan 05 12:28:00 m-vm systemd[1]: Started irqbalance.service - irqbalance daemon.

Nothing more will come out of it.

Now then there was this upstream change:

https://github.com/Irqbalance/irqbalance/commit/75a15c5dbe6b3a1fd50569b94359d22ae4116285

But it not only set foreground automatically.
It also set journal_logging=1

If I go to mantic I can get the very same:
$ echo 'IRQBALANCE_ARGS="--journal"' >> /etc/default/irqbalance
$ systemctl restart irqbalance
$ journalctl -u irqbalance -f
...
Jan 05 12:37:42 m-vm irqbalance[1575]:

                                       -----------------------------------------------------------------------------

So the actual change is that it now logs to journal (good) and due to that this 10 second break line is there (bad).

Analyzed and reported upstream
- https://github.com/Irqbalance/irqbalance/issues/292
Created a simple fix and proposed it there
- https://github.com/Irqbalance/irqbalance/pull/293
Created a MR for the same fix in Ubuntu until resolved upstream
- https://code.launchpad.net/~paelzer/ubuntu/+source/irqbalance/+git/irqbalance/+merge/458083
PPA to test:
- https://launchpad.net/~paelzer/+archive/ubuntu/lp-2046470-fix-log-spam-noble

The PPA works for me, let us wait what a reviewer says about the MR.

Upstream didn't respond quickly, but it seems ok to reduce the annoyance of this in Ubuntu with a small detla until we know how it settles there.

MR reviewed, fix uploaded.

This bug was fixed in the package irqbalance - 1.9.3-2ubuntu1

---------------
irqbalance (1.9.3-2ubuntu1) noble; urgency=medium

  * d/p/lp-2046470-Stop-log-spam-due-to-debug-message-from-scan.patch:
    reduce log spam by debug message (LP: #2046470)

 -- Christian Ehrhardt <email address hidden> Fri, 05 Jan 2024 14:30:02 +0100

It seems we raced on this,
I tested 1.9.3--1 initially 1.9.3-while -2 was stuck in proposed with an unrelated FTFBS.
Then I fixed it on the latest.

But there it got [1] added which fixes the same the upstream way.

Testing that, and probably uploading a revert.

Thanks Paride for making me aware.

[1]: https://salsa.debian.org/debian/irqbalance/-/blob/debian/latest/debian/patches/filter-console-only-output-when-using-journal-mode.debpatch

Well, now this is double-fixed in Ubuntu, I hope they don't cancel out :P

I was asking myself how you added your .patch file despite *.patch being in upstream .gitignore; I suppose you used `git add --force` (TIL).

Yep, the git/patch problem was a common case for me.

Tested and works with just one of the fixes.
While it loses my output simplification that is not worth to retain, uploaded a revert as 1.9.3-2ubuntu2 and it can be a sync when there is a newer version in Debian.