syslog output every day at the same time

[thomas23272]

Greetings,

Ever since having installed 12.3, I've been receiving syslog output on every tty at precisely 17:30 every day.
Here is yesterday's, verbatim:

Message from syslogd@the-matrix at Jun  8 17:30:14 ...
 kernel:[126254.813700] Process find (pid: 9919, ti=c78cc000 task=f51b20b0 task.ti=c78cc000)

Message from syslogd@the-matrix at Jun  8 17:30:14 ...
 kernel:[126254.813702] Stack:

Message from syslogd@the-matrix at Jun  8 17:30:14 ...
 kernel:[126254.813736] Call Trace:

Message from syslogd@the-matrix at Jun  8 17:30:14 ...
 kernel:[126254.813803] Code: c7 43 2c 00 00 00 00 89 83 88 00 00 00 8b 55 1c 89 d8 e8 d7 34 00 00 f6 43 25 40 0f 85 45 01 00 00 8b 85 c0 00 00 00 85 c0 74 0f <8b> 00 e8 1c 1c f5 ff 84 c0 0f 85 84 00 00 00 31 c0 8b 54 24 04

Message from syslogd@the-matrix at Jun  8 17:30:14 ...
 kernel:[126254.813865] EIP: [<c0342fbd>] do_dentry_open+0xdd/0x230 SS:ESP 0068:c78cde10

And today's

Message from syslogd@the-matrix at Jun  9 17:30:18 ...
 kernel:[151063.428473] Process find (pid: 17258, ti=c6de8000 task=cae04430 task.ti=c6de8000)

Message from syslogd@the-matrix at Jun  9 17:30:18 ...
 kernel:[151063.428475] Stack:

Message from syslogd@the-matrix at Jun  9 17:30:18 ...
 kernel:[151063.428509] Call Trace:

Message from syslogd@the-matrix at Jun  9 17:30:18 ...
 kernel:[151063.428576] Code: c7 43 2c 00 00 00 00 89 83 88 00 00 00 8b 55 1c 89 d8 e8 d7 34 00 00 f6 43 25 40 0f 85 45 01 00 00 8b 85 c0 00 00 00 85 c0 74 0f <8b> 00 e8 1c 1c f5 ff 84 c0 0f 85 84 00 00 00 31 c0 8b 54 24 04

Message from syslogd@the-matrix at Jun  9 17:30:18 ...
 kernel:[151063.428640] EIP: [<c0342fbd>] do_dentry_open+0xdd/0x230 SS:ESP 0068:c6de9e10

Right before this appears everywhere, the processor usage is at 100%.
My system specifications, should they be relevant, are below, in my signature.

What I'd like to know is: what is this, is there anything I should do about it, and how do I make it stop appearing everywhere?

Thanks,
Thomas

[robin_listas]

On 2014-06-10 02:46, thomas23272 wrote:
>
> Greetings,
>
> Ever since having installed 12.3, I've been receiving syslog output on
> every tty at precisely 17:30 every day.

Edit "/etc/sysconfig/cron", and change this line:

SYSLOG_ON_NO_ERROR="yes"

Then wait for the next time. When it happens again, look on the file "/var/log/messages" (you can do it in a terminal, with less, or rather "sudo less whateverfile") around that time or a bit earlier. You should see entries similar to these:

<1.6> 2014-06-08 23:33:12 Telcontar run-crons 10862 - -  leafnode: OK
<1.6> 2014-06-08 23:33:16 Telcontar run-crons 10862 - -  logrotate: OK
<1.6> 2014-06-08 23:33:16 Telcontar run-crons 10862 - -  mdadm: OK
<1.6> 2014-06-08 23:35:07 Telcontar run-crons 10862 - -  mlocate.cron: OK
<1.6> 2014-06-08 23:35:07 Telcontar run-crons 10862 - -  packagekit-background.cron: OK
<1.6> 2014-06-08 23:35:08 Telcontar run-crons 10862 - -  suse-clean_catman: OK
<1.6> 2014-06-08 23:35:16 Telcontar run-crons 10862 - -  suse-do_mandb: OK
<1.6> 2014-06-08 23:35:25 Telcontar run-crons 10862 - -  suse-texlive: OK
<1.6> 2014-06-08 23:35:25 Telcontar run-crons 10862 - -  suse.cron-sa-update: OK
<1.6> 2014-06-08 23:35:26 Telcontar run-crons 10862 - -  suse.de-backup-rc.config: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-backup-rpmdb: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-check-battery: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-cron-local: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-faxcron: OK

I guess that your problem should happen after the "?locate" line, but could be on another one.

You have a find job started by cron, probably, which crashes, triggers a kernel oops or something similar, and sends a WALL (emergency level syslog messages generate a wall).

Possibly there is a full Oops block in there.


--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)

[tsu2]

Message from syslogd@the-matrix at Jun 8 17:30:14 ...
kernel:[126254.813700] Process find (pid: 9919, ti=c78cc000 task=f51b20b0 task.ti=c78cc000)

I wonder if that's just the find utility database updating (default once a day).
I haven't investigated exactly how the database update looks, only know that by default it happens once /24hrs.

If it is the database updating, although I should think it would run as a background process, I'd also think it's likely that such an intensive process (indexing all the file name text strings on your disk(s) in only a minute or so) is likely going to redline the processor (and possibly disk I/O).

IIRC based on some reading I did years ago, typically there are two "find" apps, one that's embedded in the Desktop Office suites (like Libreoffice) and the other as the standalone app (which also shares the database with locate), so you don't have to install the findutils to experience this.

TSU

[robin_listas]

On 2014-06-11 15:56, tsu2 wrote:
>
>> Message from syslogd@the-matrix at Jun 8 17:30:14 ...
>> kernel:[126254.813700] Process find (pid: 9919, ti=c78cc000
>> task=f51b20b0 task.ti=c78cc000)
>
> I wonder if that's just the find utility database updating (default once
> a day).

That's one of them; there are other find runs on cron, looking for
specific files or in certain paths.

--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)

[thomas23272]

Sorry for the late reply. (I told the forum to send me an email when there was a new reply, but I guess it didn't.)

On 2014-06-10 02:46, thomas23272 wrote:
>
> Greetings,
>
> Ever since having installed 12.3, I've been receiving syslog output on
> every tty at precisely 17:30 every day.

Edit "/etc/sysconfig/cron", and change this line:

SYSLOG_ON_NO_ERROR="yes"

Then wait for the next time. When it happens again, look on the file "/var/log/messages" (you can do it in a terminal, with less, or rather "sudo less whateverfile") around that time or a bit earlier. You should see entries similar to these:

<1.6> 2014-06-08 23:33:12 Telcontar run-crons 10862 - -  leafnode: OK
<1.6> 2014-06-08 23:33:16 Telcontar run-crons 10862 - -  logrotate: OK
<1.6> 2014-06-08 23:33:16 Telcontar run-crons 10862 - -  mdadm: OK
<1.6> 2014-06-08 23:35:07 Telcontar run-crons 10862 - -  mlocate.cron: OK
<1.6> 2014-06-08 23:35:07 Telcontar run-crons 10862 - -  packagekit-background.cron: OK
<1.6> 2014-06-08 23:35:08 Telcontar run-crons 10862 - -  suse-clean_catman: OK
<1.6> 2014-06-08 23:35:16 Telcontar run-crons 10862 - -  suse-do_mandb: OK
<1.6> 2014-06-08 23:35:25 Telcontar run-crons 10862 - -  suse-texlive: OK
<1.6> 2014-06-08 23:35:25 Telcontar run-crons 10862 - -  suse.cron-sa-update: OK
<1.6> 2014-06-08 23:35:26 Telcontar run-crons 10862 - -  suse.de-backup-rc.config: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-backup-rpmdb: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-check-battery: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-cron-local: OK
<1.6> 2014-06-08 23:35:30 Telcontar run-crons 10862 - -  suse.de-faxcron: OK

I guess that your problem should happen after the "?locate" line, but could be on another one.

You have a find job started by cron, probably, which crashes, triggers a kernel oops or something similar, and sends a WALL (emergency level syslog messages generate a wall).

Possibly there is a full Oops block in there.


--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)

There was, although today it decided to do it half an hour earlier.
Today's messages: http://pastebin.com/HLewWELb.

As you can see, there are mentions of AppArmor before the find process. Does that have anything to do with it?

I wonder if that's just the find utility database updating (default once a day).
I haven't investigated exactly how the database update looks, only know that by default it happens once /24hrs.

If it is the database updating, although I should think it would run as a background process, I'd also think it's likely that such an intensive process (indexing all the file name text strings on your disk(s) in only a minute or so) is likely going to redline the processor (and possibly disk I/O).

The processor(one of two hardware threads) is fully used while it's running. When I was quick enough to catch it, there appeared to be no command line(just "find").
I'm not sure about I/O. / is an SSD, and /home is an HDD.

Thanks again.

[robin_listas]

On 2014-06-13 02:46, thomas23272 wrote:
>
> Sorry for the late reply.

No problem.

> (I told the forum to send me an email when
> there was a new reply, but I guess it didn't.)

It is not reliable, fails now and then.


> There was, although today it decided to do it half an hour earlier.
> Today's messages: http://pastebin.com/HLewWELb.

Did you edit /etc/sysconfig/cron?


> As you can see, there are mentions of AppArmor before the find process.
> Does that have anything to do with it?

No, not really. They confirm that there is a cronjob running that
includes a "su" command. It is caused by having "pam_apparmor", but it
not being configured. Just remove that package (or configure it).

See https://bugzilla.novell.com/show_bug.cgi?id=807130


About the log, it does not show what exact cronjob was running, either
because the string is earlier, or because you did not do the edit to
"/etc/sysconfig/cron" I requested.

however, that it tries to do "su" to "nobody" is symptomatic of "locate".


There is a kernel bug and oops detected in the log.

2014-06-12T17:00:27.567033-07:00 the-matrix kernel: [211122.087609] Pid:
27075, comm: find Tainted: P      D    O 3.7.10-1.16-desktop #1
Supermicro P4SCE/P4SCE

However, your kernel is tainted with a proprietary package, so that the
kernel devs will probably refuse to look at it. You have to remove that
kernel module and reproduce the problem in order to report it.

Kernel Module
Packages
http://nullr0ute.com/2013/12/kernel-...-descriptions/

Looking at the list, you have got:

* 'P' - Proprietary module has been loaded.
* 'D' - Kernel has oopsed before



>> If it is the database updating, although I should think it would run as
>> a background process, I'd also think it's likely that such an intensive
>> process (indexing all the file name text strings on your disk(s) in only
>> a minute or so) is likely going to redline the processor (and possibly
>> disk I/O).
>>
> The processor(one of two hardware threads) is fully used while it's
> running. When I was quick enough to catch it, there appeared to be no
> command line(just "find").
> I'm not sure about I/O. / is an SSD, and /home is an HDD.


On magnetic media, find taxes the disk, not the cpu.

--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)

[thomas23272]

Did you edit /etc/sysconfig/cron?

I did, yes (should have said so...my bad!).

> As you can see, there are mentions of AppArmor before the find process.
> Does that have anything to do with it?[/color]

No, not really. They confirm that there is a cronjob running that
includes a "su" command. It is caused by having "pam_apparmor", but it
not being configured. Just remove that package (or configure it).

See https://bugzilla.novell.com/show_bug.cgi?id=807130

Thanks for the link, I removed it (no real reason to have it on a desktop).

There is a kernel bug and oops detected in the log.

2014-06-12T17:00:27.567033-07:00 the-matrix kernel: [211122.087609] Pid:
27075, comm: find Tainted: P      D    O 3.7.10-1.16-desktop #1
Supermicro P4SCE/P4SCE

However, your kernel is tainted with a proprietary package, so that the
kernel devs will probably refuse to look at it. You have to remove that
kernel module and reproduce the problem in order to report it.

Kernel Module
Packages
http://nullr0ute.com/2013/12/kernel-...-descriptions/

Looking at the list, you have got:

* 'P' - Proprietary module has been loaded.
* 'D' - Kernel has oopsed before

The only proprietary module I ever recall installing is nvidia's graphics driver.
If I ever have more time I'll certainly try to let it happen with that unloaded, and I'll file a bug report.

On magnetic media, find taxes the disk, not the cpu.

Well, in any case, right before syslog printed everywhere, one core was at 100%, and ps showed that find was indeed the culprit.

[robin_listas]

On 2014-06-13 07:26, thomas23272 wrote:

> robin_listas;2648694 Wrote:
>>
>> Did you edit /etc/sysconfig/cron?
> I did, yes (should have said so...my bad!).

Ah, then maybe somewhere after those entries you have another one about
a failed cron job, even an email about it. And before it there should be
another entry about the last sucesfull daily cronjob.


>> Looking at the list, you have got:
>>
>> * 'P' - Proprietary module has been loaded.
>> * 'D' - Kernel has oopsed before
>>
> The only proprietary module I ever recall installing is nvidia's
> graphics driver.

That's one they particularly hate.

> If I ever have more time I'll certainly try to let it happen with that
> unloaded, and I'll file a bug report.

I had to report a kernel crash recently, and my kernel was tainted for
the same reason. What I did was simply blacklist the nvidia module,
remove the blacklist for nouveau, and rebuild initrd. That suffices for
text mode (my bug was easy to reproduce in text mode). I did not have to
actually remove the nvidia driver.

You could the same. Prepare it about an hour before the job should run,
then reboot to level 3, and wait it out... once it happens and is
logged, undo the changes, reboot with nvidia to graphical mode, extract
the messages log of that 100 minutes session (only one session log, not
more is needed, from boot to halt), and create a bugzilla attaching it.

Then wait... That's all you can do. They may take months or years to
start looking at it, if they do. Depends if it triggers the interest of
a particular developer.

But if you don't report, it will never ever be solved.

After that, you could consider disabling the locate database update run...


It should also be possible to tune the hour the cronjob runs. You could
adjust it to your sleep time, and just leave the computer running, text
mode with no nvidia driver loaded, as described above.

Notice that it is not enough to boot in text mode: the nvidia module
gets loaded even if not used. As soon as it loads, the kernel gets
marked "tainted" for the entire session. You need to blacklist it (and
whitelist nouveau) and rebuild initrd, because it is loaded very soon.

>
> robin_listas;2648694 Wrote:
>>
>>
>> On magnetic media, find taxes the disk, not the cpu.
>>
> Well, in any case, right before syslog printed everywhere, one core was
> at 100%, and ps showed that find was indeed the culprit.

If you run "ps afxu | less" in a terminal, you get the hierarchy tree of
what called what, so that you could capture at that moment what called find.

You might create your own daily cronjob running a bunch of the above ps
calls dumped to a file to capture the event - a brute force approach.

But it seems to be "locate", guessing.

In your case, with 'find' happening on an ssd, I would expect to really
find things very fast (no head search movement all across the platters),
so it should be generating a fast flow of data up to the capacity of the
sata bus, or of the board and cpu buses to catch it - so that the cpu
could be up to its head real busy - which till invention of SSDs
probably never happened. Just a wild guess.

I don't see why that should crash 'find', even less the kernel, but...
hey, I don't know how 'find' was programmed.

Another hypothesis would be 'find' searching an area of the disk(s) with
bad sectors or some other problem.


--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)

[thomas23272]

Ah, then maybe somewhere after those entries you have another one about
a failed cron job, even an email about it. And before it there should be
another entry about the last sucesfull daily cronjob.

Alas, no: neither /var/log/messages nor the root mailbox has anything about a failed cron job in it.

I had to report a kernel crash recently, and my kernel was tainted for
the same reason. What I did was simply blacklist the nvidia module,
remove the blacklist for nouveau, and rebuild initrd. That suffices for
text mode (my bug was easy to reproduce in text mode). I did not have to
actually remove the nvidia driver.

You could the same. Prepare it about an hour before the job should run,
then reboot to level 3, and wait it out... once it happens and is
logged, undo the changes, reboot with nvidia to graphical mode, extract
the messages log of that 100 minutes session (only one session log, not
more is needed, from boot to halt), and create a bugzilla attaching it.

Then wait... That's all you can do. They may take months or years to
start looking at it, if they do. Depends if it triggers the interest of
a particular developer.

But if you don't report, it will never ever be solved.

After that, you could consider disabling the locate database update run...

It should also be possible to tune the hour the cronjob runs. You could
adjust it to your sleep time, and just leave the computer running, text
mode with no nvidia driver loaded, as described above.

Notice that it is not enough to boot in text mode: the nvidia module
gets loaded even if not used. As soon as it loads, the kernel gets
marked "tainted" for the entire session. You need to blacklist it (and
whitelist nouveau) and rebuild initrd, because it is loaded very soon.

Thanks, I'll definitely do that.

If you run "ps afxu | less" in a terminal, you get the hierarchy tree of
what called what, so that you could capture at that moment what called find.

You might create your own daily cronjob running a bunch of the above ps
calls dumped to a file to capture the event - a brute force approach.

But it seems to be "locate", guessing.

Actually, it turns out my eyes deceived me: find was not the culprit, but gzip -9 was.
I'm not quite sure why or how that happened, but it does make a lot more sense.
(Specifically, it was cron.daily/suse.de-backup-rpmdb, but that is unrelated to this)

In your case, with 'find' happening on an ssd, I would expect to really
find things very fast (no head search movement all across the platters),
so it should be generating a fast flow of data up to the capacity of the
sata bus, or of the board and cpu buses to catch it - so that the cpu
could be up to its head real busy - which till invention of SSDs
probably never happened. Just a wild guess.

I don't see why that should crash 'find', even less the kernel, but...
hey, I don't know how 'find' was programmed.

Another hypothesis would be 'find' searching an area of the disk(s) with
bad sectors or some other problem.

If that causes such a drastic error, then there are many things wrong with the kernel as a whole.

Thanks again,
Thomas

[robin_listas]

On 2014-06-15 06:36, thomas23272 wrote:
>
> robin_listas;2648715 Wrote:

>> Ah, then maybe somewhere after those entries you have another one about
>> a failed cron job, even an email about it. And before it there should
>> be
>> another entry about the last sucesfull daily cronjob.
> Alas, no: neither /var/log/messages nor the root mailbox has anything
> about a failed cron job in it.

Weird.

....

> Thanks, I'll definitely do that.

Good :-)


>> But it seems to be "locate", guessing.
>>
> Actually, it turns out my eyes deceived me: find was not the culprit,
> but gzip -9 was.

Oh?

> I'm not quite sure why or how that happened, but it does make a lot more
> sense.
> (Specifically, it was cron.daily/suse.de-backup-rpmdb, but that is
> unrelated to this)

Please clarify. suse.de-backup-rpmdb is the cronjob that triggers the
kernel fault?

It does not run 'find', AFAIK. It uses gzip -9, indeed. You could edit
the script to use a different compressor, like xz.

You can directly call "/etc/cron.daily/suse.de-backup-rpmdb" to test it
(you have to delete "/var/adm/backup/rpmdb/rpmdb_recent_md5" to force it
to run), then list the directory for checking. (ls -ltr
/var/adm/backup/rpmdb).

I just changed the script to use xz myself. It compresses to half the size:

#        if gzip -9 < /var/lib/rpm/$PACKAGEDBFILE > $NEWNAME.gz; then
if xz < /var/lib/rpm/$PACKAGEDBFILE > $NEWNAME.xz; then
....
#            rm -f $NEWNAME $NEWNAME.gz
rm -f $NEWNAME $NEWNAME.xz

It appears to work.

Ah, and this one:

while [ -e $NEWNAME -o -e $NEWNAME.xz ] ; do

I'll watch out how it goes.


> robin_listas;2648715 Wrote:
>>
>> Another hypothesis would be 'find' searching an area of the disk(s) with
>> bad sectors or some other problem.
>>
> If that causes such a drastic error, then there are many things wrong
> with the kernel as a whole.

Well, things happen.

--
Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 "Bottle" at Telcontar)