microceph spams logs with debug messages

[tregubovav-dev]

I'm deploying LXD+microceph clusters on top of Raspberry PI instances.
I found that microceph spams syslog with debug messages in addition to tons of debug messages in /var/snap/microceph/common/logs as described in issue #163.
How to make microceph's daemons log level configurable?

[tregubovav-dev]

Folks, we need to resolve the issue, but not only to document it.

The real issue is that there is no way to configure microcephd's log level yet. And this is big problem for instances running on IoT devices with eMMC storage. Syslog is spammed with "microceph.daemon" messages which are not needed normal operation. Asn as result eMMC storage wears out too fast,

This line of code enforces debug level by default . However, snap does not support configuration hook, so there is no way to change microcephd parameters via snap commands.

[sabaini]

Should be fixed in /edge via PR #294 , docs in #307

[tregubovav-dev]

Did this fix arrived to snap reef/stable: 18.2.0+snap450240f5dd 2024-04-09 (979) ?
I updated my lab to this version and see following behavior:

1. log set-level and log get-level options are available and a I can set level of logging through microceph command-line parameters
2. microceph logging level is still debug after changing log level to any level between 0 and 5 or 7, or (panic, fatal, error, warning, info, trace).
3. logging level resets to 0 after restarting microceph snap or restarting host.

My environment:

• Cluster of Raspberry Pi 4
• Ubuntu 23.10 Server (ARM)

P.S.
I looked to pipeline and found that "Test log operation" stage does not validate log output changes. It validates that log changes is accepted by control plane in active session.

[UtkarshBhatthere]

Thanks for reporting this @tregubovav-dev will take a look at this.
cc: @sabaini @lmlg

[lmlg]

just to get this right - You used log set-level to something more suitable, and still it appears that the log level is set at DEBUG? If so, we'll need to look at the underlying library, since we are reasonably sure that the level is changed, based on our CI tests, as you've pointed out.

[tregubovav-dev]

I will provide additional details in couple hours.
I will try to prepare functional test-case later today.

[tregubovav-dev]

Steps to reproduce

Please run script below:

PID=$(pidof microcephd); for LEVEL in 1 2 3 4 5 6 0;  \
do echo "<<< START >>>"; \
printf "Current log level: $(sudo microceph log get-level)\n" && \
sudo microceph log set-level $LEVEL;  \
printf "Log level changed to: $(sudo microceph log get-level)\n" && \
echo "======= log ======" && \
sleep 10s && journalctl --no-pager -S -11s _PID=$PID; \
printf "<<<  END  >>>\n\n"; \
done

review log outputs and see that microcephd continues generate level=debug messages to the system log independently of log level set by sudo microceph log set level $LEVEL command.

My environment information:

I have 7 Raspberry Pi 4 SBC that host microceph and LXD clusters.

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 23.10
Release: 23.10
Codename: mantic

$ sudo microceph --version
ceph-version: 18.2.0-0ubuntu3~cloud0; microceph-git: 450240f

$ sudo snap info microceph
name: microceph
summary: Simple clustered Ceph deployment
publisher: Canonical✓
store-url: https://snapcraft.io/microceph
contact: https://matrix.to/#/#ubuntu-ceph:matrix.org
license: AGPL-3.0
...
installed: 18.2.0+snap450240f5dd (979) 78MB in-cohort,held

$ sudo lxd --version
5.19

$ sudo snap info lxd
name: lxd
summary: LXD - container and VM manager
publisher: Canonical✓
store-url: https://snapcraft.io/lxd
contact: https://github.com/canonical/lxd/issues
license: unset
...
installed: 5.19-8635f82 (26202) 141MB in-cohort,held

$ sudo lshw -short
H/W path Device Class Description
system Raspberry Pi 4 Model B Rev 1.4
/0 bus Motherboard
/0/1 processor cpu
/0/1/0 memory 32KiB L1 Cache
/0/2 processor cpu
/0/2/0 memory 32KiB L1 Cache
/0/3 processor cpu
/0/3/0 memory 32KiB L1 Cache
/0/4 processor cpu
/0/4/0 memory 32KiB L1 Cache
/0/5 processor l2-cache0
/0/6 memory 7808MiB System memory
/0/0 bridge BCM2711 PCIe Bridge
/0/0/0 bus VL805/806 xHCI USB 3.0 Controller
/0/0/0/0 usb1 bus xHCI Host Controller
/0/0/0/0/1 bus USB2.0 Hub
/0/0/0/1 usb2 bus xHCI Host Controller
/0/0/0/1/1 scsi0 storage PSSD T7
/0/0/0/1/1/0.0.0 /dev/sda disk 1TB PSSD T7
/1 usb3 bus DWC OTG Controller
/2 mmc0 bus MMC Host
/2/aaaa /dev/mmcblk0 disk 127GB SN128
/2/aaaa/1 /dev/mmcblk0p1 volume 256MiB Windows FAT volume
/2/aaaa/2 /dev/mmcblk0p2 volume 64GiB Linux filesystem partition
/3 mmc1 bus MMC Host
/3/1 generic SDIO Device
/3/1/1 mmc1:0001:1 network 43430
/3/1/2 mmc1:0001:2 generic 43430
/3/1/3 mmc1:0001:3 communication 43430
/4 card0 multimedia Headphones
/5 eth0 network Ethernet interface

[tregubovav-dev]

just to get this right - You used log set-level to something more suitable, and still it appears that the log level is set at DEBUG? If so, we'll need to look at the underlying library, since we are reasonably sure that the level is changed, based on our CI tests, as you've pointed out.

My concern is to this test:

    - name: Test log operations
      run: |
        set +e
        sudo microceph log set-level warning
        output=$(sudo microceph log get-level)
        if [[ "$output" != "3" ]] ; then echo "incorrect log level: $output"; exit 1; fi

It does verify that log level configuration is changed, but it does not validate that the log configuration change is applied to the log producer.

Script provided in my previous comment can be adjusted for validation logs after log level changes.

[roosterfish]

Hello, just found about this bug report and I guess the root cause for the daemon's log debug messages lies in https://github.com/canonical/microceph/blob/main/microceph/cmd/microcephd/main.go#L107. If you don't proactively set --debug false when starting microcephd it will print debug log messages.

As --debug true is the default can we either add this to https://github.com/canonical/microceph/blob/main/snapcraft/commands/daemon.start or set the default value of flagLogDebug to false?

[tomponline]

I installed microceph recently and found it to be quite noisy in the logs due to debug mode be enabled by default.