Page 1 of 2 12 LastLast
Results 1 to 10 of 15

Thread: syslog output every day at the same time

  1. #1
    Join Date
    Dec 2010
    Location
    California, USA
    Posts
    50

    Default syslog output every day at the same time

    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:
    Code:
    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
    Code:
    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
    SuperMicro P4SCE (Pentium 4 HT)
    3 GB DDR1 RAM
    nVidia GeForce FX 5500
    openSUSE 12.3(3.7.10-1.36-desktop) XFCE

  2. #2
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: syslog output every day at the same time

    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:

    Code:
    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:


    Code:
    <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)

  3. #3
    Join Date
    Jun 2008
    Location
    San Diego, Ca, USA
    Posts
    11,397
    Blog Entries
    2

    Default Re: syslog output every day at the same time

    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

  4. #4
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: syslog output every day at the same time

    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)

  5. #5
    Join Date
    Dec 2010
    Location
    California, USA
    Posts
    50

    Default Re: syslog output every day at the same time

    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.)
    Quote Originally Posted by robin_listas View Post
    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:

    Code:
    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:


    Code:
    <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?

    Quote Originally Posted by tsu2 View Post
    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.
    SuperMicro P4SCE (Pentium 4 HT)
    3 GB DDR1 RAM
    nVidia GeForce FX 5500
    openSUSE 12.3(3.7.10-1.36-desktop) XFCE

  6. #6
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: syslog output every day at the same time

    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.

    Code:
    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)

  7. #7
    Join Date
    Dec 2010
    Location
    California, USA
    Posts
    50

    Default Re: syslog output every day at the same time

    Quote Originally Posted by robin_listas View Post
    Did you edit /etc/sysconfig/cron?
    I did, yes (should have said so...my bad!).

    Quote Originally Posted by robin_listas View Post
    > 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).

    Quote Originally Posted by robin_listas View Post
    There is a kernel bug and oops detected in the log.

    Code:
    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.

    Quote Originally Posted by robin_listas View Post

    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.
    SuperMicro P4SCE (Pentium 4 HT)
    3 GB DDR1 RAM
    nVidia GeForce FX 5500
    openSUSE 12.3(3.7.10-1.36-desktop) XFCE

  8. #8
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: syslog output every day at the same time

    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)

  9. #9
    Join Date
    Dec 2010
    Location
    California, USA
    Posts
    50

    Default Re: syslog output every day at the same time

    Quote Originally Posted by robin_listas View Post
    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.


    Quote Originally Posted by robin_listas View Post
    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.

    Quote Originally Posted by robin_listas View Post
    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)

    Quote Originally Posted by robin_listas View Post
    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.
    Quote Originally Posted by robin_listas View Post
    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
    SuperMicro P4SCE (Pentium 4 HT)
    3 GB DDR1 RAM
    nVidia GeForce FX 5500
    openSUSE 12.3(3.7.10-1.36-desktop) XFCE

  10. #10
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: syslog output every day at the same time

    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:

    Code:
    #        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:

    Code:
    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)

Page 1 of 2 12 LastLast

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •