thermald spamming syslog with 'sysfs write failed constraint_0_power_limit_uw'

[Graham Mitchell]

[SRU REQUEST, Xenial, Yakkety]

Thermald is spamming the log with error messages on sysfs write failure messages. Demote these to debug level errors so that they aren't logged unless running in debug mode.

[FIX]

See comment #24, with the fix the messages are not logged when in normal non-debug running mode.

[REGRESSION POTENIAL]

Minimal, this just reduces the logging spam by turning messages into debug only for when running in debug mode.

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

This seems somewhat related to https://bugs.launchpad.net/ubuntu/+source/thermald/+bug/1543046

For some reason thermald is writing the message "sysfs write failed constraint_0_power_limit_uw" to the syslog every few seconds. However, there's nothing in the kernel log.

$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.10
DISTRIB_CODENAME=yakkety
DISTRIB_DESCRIPTION="Ubuntu 16.10"

$ uname -a
Linux graham-desktop 4.8.0-34-generic #36-Ubuntu SMP Wed Dec 21 17:24:18 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

$ dpkg -l | grep thermald
ii thermald 1.5.3-4 amd64 Thermal monitoring and controlling daemon

$ grep "sysfs write failed constraint_0_power_limit_uw" /var/log/syslog | wc -l
14160

$ grep thermald /var/log/kern.log | wc -l
0

I'm an experienced Linux user but not an experienced bug submitter, so please let me know if I have failed to provide any necessary info. Am happy to attach additional logs.

[Colin Ian King (colin-king)]

@Graham,

I'm interested in seeing all the kernel log messages as that may give a hint on why this is happening. Can you attach it to the bug report?

I suspect you may also be getting the kernel reporting "powercap intel-rapl:0: package locked by BIOS, monitoring only"

Colin

[Colin Ian King (colin-king)]

@Srinivas, any ideas? It seems that the rapl interface is not writable, which is a surprise to me.

[Colin Ian King (colin-king)]

@Graham, just one more thing, which processor do you have?

grep "model name" /proc/cpuinfo

[Graham Mitchell (graham-grahammitchell)]

$ grep "model name" /proc/cpuinfo
model name : Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz (repeated 8 times)

And there's really nothing in the kernel log, I swear. I've attached it just so you can see for yourself.

[Colin Ian King (colin-king)]

Hi, can you run:

journalctl -S 2017-01-01 | grep thermald > thermald.log

and attach the log to the bug. Thanks!

[Graham Mitchell (graham-grahammitchell)]

Attached. I'll save you some suspense, though; it's literally the same line over and over 38,000 times.

$ cut -b 16- thermald.log | sort | uniq -c
  38147 graham-desktop thermald[1086]: sysfs write failed constraint_0_power_limit_uw

[Colin Ian King (colin-king)]

Thanks, the frequency of the spamming is a useful data point. Finally, I'd like to get some more context around today's spamming messages, so can you run:

journalctl -S 2017-01-16 > thermald-2.log

and attach that too. Thanks again.

[Colin Ian King (colin-king)]

I'd also like to see how the write failure is occurring and get some context around that, so can you also trace thermald as follows:

sudo strace -p $(pidof thermald) >& strace.log

let thus run for a minute or so, and then hit Control C and attach the strace.log file to the bug report too.

[Graham Mitchell (graham-grahammitchell)]

Yikes. Well, it looks like I need to disable SSH password authentication but here it is.

[Graham Mitchell (graham-grahammitchell)]

I attached the strace log.

Is there a chance it's related to this?

http://unix.stackexchange.com/questions/285529/internet-stops-working-failed-to-add-run-systemd-ask-password-to-directory-wa

https://bugzilla.redhat.com/show_bug.cgi?id=894483

After I updated /etc/ssh/sshd_config I got an interesting error:
$ sudo service ssh restart
Failed to add /run/systemd/ask-password to directory watch: No space left on device

...which leads me to wonder if the Crashplan back-up service is the most likely culprit. "It uses many inotify watches and, eventually, eats them all up."

[Colin Ian King (colin-king)]

I'm more included to wonder why the write to the rapl sysfs file is not working, it should do. So, that strace didn't quite capture the failure, so do you mind re-running it once more, this time for ~10 minutes of time.

sudo strace -p $(pidof thermald) >& strace-2.log

Thanks.

[Graham Mitchell (graham-grahammitchell)]

I've got good and bad news. I configured Crashplan to no longer "Watch file system in real-time" and rebooted (to get rid of any stale open inotify watches).

And so far there hasn't been a single 'sysfs write failed constraint_0_power_limit_uw' message written to the syslog since rebooting (19 minutes and counting).

So the bad news is I can't provide good diagnostic information at the moment unless it starts back up again.

[Graham Mitchell (graham-grahammitchell)]

For the record, Crashplan is backing up a LOT of files for me: 3,324,286 files, so "watch file system in real-time" really could have been a LOT of inotify watches.

25 minutes of uptime and still no thermald messages to the syslog.

[Colin Ian King (colin-king)]

Thanks for those observations. It may be that we're just low on free file descriptors or some other resource because of all the inotify watches and hence thermald can't open the file for writing. It's hard to tell. Anyhow, thermald should not be spamming the log, so we need to fix thermald not to spam the log so aggressively.

[Graham Mitchell (graham-grahammitchell)]

Thanks for all your attention to my little issue. Sorry for rebooting in the middle of a diagnostic session; I guess that's bad form.

[Graham Mitchell (graham-grahammitchell)]

I'll reopen the bug if they return at some point and try to get you that strace.

[Colin Ian King (colin-king)]

Thank for you help in assisting me to debug this. I'm very happy to pick this up again if you see the issue once more.

[Graham Mitchell (graham-grahammitchell)]

Well, it took a week but the messages started back up again. I did a 10-minute strace, so hopefully the log has the info you're looking for.

[Colin Ian King (colin-king)]

Hi Graham,

I've created a new package with a fix to this issue. Can you install it and give it a soak test to see if this stops the log spamming. Use.

sudo add-apt-repository ppa:colin-king/thermald-lp1656528
sudo apt-get update && sudo apt-get upgrade

I suggest loading the machine for a good few minutes to see if you can trip the RAPL warnings. One can use a tool such as stress-ng to do this, using:

sudo apt-get install stress-ng
stress-ng --cpu 0 -t 300s

(stresses all the CPUs for 300 seconds).

Let me know if this fixes the issue or not.

[Graham Mitchell (graham-grahammitchell)]

The VERY first time I ran the stress test there was a single message:

Feb 1 18:04:11 graham-desktop stress-ng: invoked with 'stress-ng --cpu 0 -t 300s' by user 1000
Feb 1 18:04:11 graham-desktop stress-ng: system: 'graham-desktop' Linux 4.8.0-34-generic #36-Ubuntu SMP Wed Dec 21 17:24:18 UTC 2016 x86_64
Feb 1 18:04:11 graham-desktop stress-ng: memory (MB): total 7891.60, free 198.99, shared 402.29, buffer 100.01, swap 8192.00, free swap 5817.87
Feb 1 18:04:17 graham-desktop thermald[9128]: sysfs write failed constraint_0_power_limit_uw

I did it twice more, about ten minutes apart and tried to use the machine while testing and the message didn't appear again.

I have to reboot my computer again because of another update, but I'll keep an eye on the syslog and keep you posted.

[Colin Ian King (colin-king)]

@Graham,

The result looks good then - we should get one write failure being logged and then that interface is disabled to stop subsequent failed writes and hence you should only see the one message.

Thanks for testing.

[Srinivas Pandruvada (srinivas-pandruvada)]

@Graham,

I see you attached kernel log, but doesn't have boot time log. Can you just boot the system and

# dmesg | grep "locked by BIOS"

[Colin Ian King (colin-king)]

FYI, I've updated the thermald package in the PPA to a version 1.5.3-5~2, this contains a proposed change as suggested by Srinivas (see below). I'd be interested to see how this works for you.

..to get the updated thermald please run:

sudo apt-get update && sudo apt-get upgrade

diff --git a/src/thd_sys_fs.cpp b/src/thd_sys_fs.cpp
index 044c8f0..055fc28 100644
--- a/src/thd_sys_fs.cpp
+++ b/src/thd_sys_fs.cpp
@@ -30,13 +30,13 @@ int csys_fs::write(const std::string &path, const
std::string &buf) {
        std::string p = base_path + path;
        int fd = ::open(p.c_str(), O_WRONLY);
        if (fd < 0) {
- thd_log_warn("sysfs write failed %s\n", p.c_str());
+ thd_log_debug("sysfs write failed %s\n", p.c_str());
                return -errno;
        }
        int ret = ::write(fd, buf.c_str(), buf.size());
        if (ret < 0) {
                ret = -errno;
- thd_log_warn("sysfs write failed %s\n", p.c_str());
+ thd_log_debug("sysfs write failed %s\n", p.c_str());
        }
        close(fd);

@@ -48,17 +48,17 @@ long long data) {
        std::string p = base_path + path;
        int fd = ::open(p.c_str(), O_WRONLY);
        if (fd < 0) {
- thd_log_warn("sysfs write failed %s\n", p.c_str());
+ thd_log_debug("sysfs write failed %s\n", p.c_str());
                return -errno;
        }
        if (::lseek(fd, position, SEEK_CUR) == -1) {
- thd_log_warn("sysfs write failed %s\n", p.c_str());
+ thd_log_debug("sysfs write failed %s\n", p.c_str());
                close(fd);
                return -errno;
        }
        int ret = ::write(fd, &data, sizeof(data));
        if (ret < 0)
- thd_log_warn("sysfs write failed %s\n", p.c_str());
+ thd_log_debug("sysfs write failed %s\n", p.c_str());
        close(fd);

        return ret;

[Graham Mitchell (graham-grahammitchell)]

Updated to the latest version of thermald and rebooted.

$ dmesg | grep "locked by BIOS"

(no output)

[Colin Ian King (colin-king)]

Thanks Graham, that's as expected.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.5.4-4

---------------
thermald (1.5.4-4) unstable; urgency=medium

  * fix spamming of logs when writes file (LP: #1656528)
    - patch from Srinivas Pandruvada at Intel, not yet mainline

 -- Colin King <email address hidden> Thu, 23 Feb 2017 09:26:23 +0000

[Colin Ian King (colin-king)]

Hello Graham, or anyone else affected,

Accepted thermald into yakkety-proposed and xenial-proposed. The package is now available in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Łukasz Zemczak (sil2100)]

The SRU change itself looks good, but what I don't like and miss is any DEP-3 headers for the included patch - or at least the Description field of that. One reason is: formalities. The other: the change is fairly small and simple in overall, but someone might start wondering why suddenly a warning message got demoted to a debug, which is not really clear without a description.
Could you please add that and re-upload with the same version number? I would reject the old ones then.

Thank you!

[Brian Murray (brian-murray)]

Hello Graham, or anyone else affected,

Accepted thermald into yakkety-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.5.3-4ubuntu1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Colin Ian King (colin-king)]

Hi Brian, I've been running thermald and overheating a laptop with stress-ng for ~30+ minutes and can't see the log spamming, so this is tested and shown to be fixed. Marking as verified for Yakkety.

[Brian Murray (brian-murray)]

Hello Graham, or anyone else affected,

Accepted thermald into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.5-2ubuntu3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Colin Ian King (colin-king)]

Hi Brian, I've been running thermald on Xenial with the -proposed thermald and overheating a laptop with stress-ng for ~30+ minutes and can't see the log spamming, so this is tested and shown to be fixed. Marking as verified for Xenial too.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.5.3-4ubuntu1

---------------
thermald (1.5.3-4ubuntu1) yakkety; urgency=medium

  * fix spamming of logs when writes file (LP: #1656528)
    - patch from Srinivas Pandruvada at Intel, not yet mainline

 -- Colin King <email address hidden> Thu, 23 Feb 2017 09:26:23 +0000

[Brian Murray (brian-murray)]

The verification of the Stable Release Update for thermald has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package thermald - 1.5-2ubuntu3

---------------
thermald (1.5-2ubuntu3) xenial; urgency=medium

  * fix spamming of logs when writes file (LP: #1656528)
    - patch from Srinivas Pandruvada at Intel, not yet mainline

 -- Colin King <email address hidden> Wed, 15 Mar 2017 17:32:33 +0000

[Andy Whitcroft (apw)]

Hello Graham, or anyone else affected,

Accepted thermald into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/thermald/1.7.0-5ubuntu4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Colin Ian King (colin-king)]

The bionic SRU test message occurred because I accidentally uploaded the package with the entire old history. This bug has already been fixed and the verification for bionic can be ignored.