Loads of strange entries in the system log

English Install/Boot/Login
#1

Hello,
I have a probem on a laptop I use, a MacBook Pro running openSUSE
Tumbleweed. I do not see this issue on any other system, also not on a
second MacBook. It is not a new problem, have seen that stuff for month
now, I never noticed any negative impact. However I cannot find out
where those messages come from in the system log file:

…]
Jul 23 14:45:30 balder pidof[7161]: can’t read from 7173/stat
Jul 23 14:45:50 balder pidof[7526]: can’t read from 7542/stat
Jul 23 14:46:42 balder pidof[8477]: can’t read from 8415/stat
Jul 23 14:46:46 balder pidof[8540]: can’t read from 8503/stat
Jul 23 14:47:02 balder pidof[8826]: can’t read from 8828/stat
Jul 23 14:47:50 balder pidof[9667]: can’t read from 9673/stat
Jul 23 14:47:54 balder pidof[9768]: can’t read from 9748/stat
Jul 23 14:48:06 balder pidof[9969]: can’t read from 9958/stat
Jul 23 14:49:54 balder pidof[11908]: can’t read from 11902/stat
Jul 23 14:50:01 balder pidof[12052]: can’t read from 12059/stat
…]

I caanot even find out what type of process causes this, when the
message appears both the reading and the read process have already
gone.

Anyone got an idea ?
arkascha

#2

We need more information:

  1. openSUSE version (12.1 or 11.4)
  2. Bit version installed, 32 or 64
  3. Desktop used: KDE or GNOME or other
  4. From what log file does this error come from?
  5. What problems are you trying to solve, exactly?

I have a bash script useful in viewing log files on your PC: S.L.A.V.E. - SuSE Logfile Automated Viewer Engine - Version 2.55 - Blogs - openSUSE Forums

Thank You,

#3
  1. openSUSE version (12.1 or 11.4)

As written I use Tumbeweed. I originally installed a 12.1 and added some tumbleweed repositories afterwards.

  1. Bit version installed, 32 or 64

Sorry, forgot that: all MBPs have 64 bits.

  1. Desktop used: KDE or GNOME or other

KDE4

  1. From what log file does this error come from?

With ‘syslog’ I referred to /var/log/messages.

  1. What problems are you trying to solve, exactly?

I am trying to gain world domination by using that top secret button I implemented here on my system. It is that secret that I don’t dare to install it anywhere else. So I guess world domination will have a somewhat ‘reduced’ area of application.
Sorry, couldn’t resist.
As written I have strange entries in my system log. As written I fail to understand what is causing these entries. So I guess the answer to that question is:
What is causing these entries ?

arkascha

#4

I looked up your error message, or at least tried to and I got no hits. As written, it does not seem to match anything, so what ever it is, its not very common. Next, most systems get lots of “error” messages on startup from the kernel as it loads. My two things to look for are:

  1. Something (hardware or software) you need to use does not work.

OR

  1. One of the error logs is growing at such a rate its going to run you out of disk space.

AND

  1. If you can answer no to 1 and 2, then NO Problems, the world is a great place to use Linux.

Of course, you can have both problems one and two on the same system, which is bad. The bash script I pointed you to, has a mode using tail, which can, as written, update the status of any of the logs it can read, once every 10 seconds. Any error log that has new entries every 10 seconds is bad and something you need to fix. Logs that change once an hour, don’t mean much and logs that only change at boot up are worth looking at, but in the end, the kernel writes a lot of “noise” to these logs, much of which, means nothing much. Now not to discourage anyone from looking, I have found potential problems in the logs which I did fix, but as I get older, I am more likely to look back at my original problems as described in 1 and 2 and always hope for 3.

Thank You,

#5

Thanks,
following your stream of thoughts I would indeed answer “no” to questions 1. and 2., since as written everything works fine on that system and the log files are kept in a ramdisk, loads of room there. When being synced back they take only 25% of the available space on the physical log volume.
But although I absolutely agree that the world is a fine place, using Linux or not, that still is not an answer to my question. My question was what might be causing these entries, not if I have to change anything or buy a new system. In my eyes there is one very important question missing in your above enumeration:
4. if you notice aspects you cannot explain and have a little spare time, use those aspects as an opportunity to learn ! Cause life is an endless stream of opportunities to learn and understand.

Thanks for taking a look at my question nevertheless.

Oh, and you asked for feedack for that little bash script: I could imagine that this is a nice tool for people who love the “commander” style of using their system. I don’t, so to be it appears more like a step into history without offering real benefit. but that is only my personal impression of course. Maybe some more solid aspects:

  • why is the dialogs visible area that small ? Why doesn’t it use the available space inside the terminal ?
  • it was pretty hard to read because of the (intended) curses like optics.
  • it left my terminal setting garbled after I exited.
    Anyway, if it helps you to use your system it is the perfect tool for you per definition. And it always is an interesting task to implement and improve such an engine. A great opportunity to learn, so keep up the work !
#6

Bash scripts are often run on small terminals and I have tried to live within the 24 x 80 that older terminals use though some information can be as long and wide as any permits. I normally set the terminal font to a 12 which makes it more readable. I mainly use KDE and konsole and so anything else may not be as viewable. And of course, the price is right for free bash scripts, source code included which you can modify as you wish.

Thank You,

#7

On 2012-07-23 15:46, arkascha wrote:
>
> Hello,
> I have a probem on a laptop I use, a MacBook Pro running openSUSE
> Tumbleweed. I do not see this issue on any other system, also not on a
> second MacBook. It is not a new problem, have seen that stuff for month
> now, I never noticed any negative impact. However I cannot find out
> where those messages come from in the system log file:
>
> …]

Please remember next time to use codetags to post these things.

Posting in Code Tags - A Guide


> Jul 23 14:45:30 balder pidof[7161]: can't read from 7173/stat
> Jul 23 14:45:50 balder pidof[7526]: can't read from 7542/stat
> Jul 23 14:46:42 balder pidof[8477]: can't read from 8415/stat
> Jul 23 14:46:46 balder pidof[8540]: can't read from 8503/stat
> Jul 23 14:47:02 balder pidof[8826]: can't read from 8828/stat
> Jul 23 14:47:50 balder pidof[9667]: can't read from 9673/stat
> Jul 23 14:47:54 balder pidof[9768]: can't read from 9748/stat
> Jul 23 14:48:06 balder pidof[9969]: can't read from 9958/stat
> Jul 23 14:49:54 balder pidof[11908]: can't read from 11902/stat
> Jul 23 14:50:01 balder pidof[12052]: can't read from 12059/stat
> ...]

> I caanot even find out what type of process causes this, when the
> message appears both the reading and the read process have already
> gone.

Well, the process that causes that is “pidof”, which is been called by something else :slight_smile:

It is not a kernel message. And I think it is trying to read from “/proc/PIDNUMBER/stat”, and
failing for some reason; perhaps the process in question has died by the time pidof is queried.

If you get a lot of those, you can temporarily rename the pidof binary and see what complain
you get. Or block it with AA so that you get a report. If you want to try the AA route I’ll
post more details on that from my notes.

–
Cheers / Saludos,

Carlos E. R.
(from 11.4 x86_64 “Celadon” at Telcontar)

#8

Hello,
first of all: sorry for not using code tags. I thought it is not required in this case and frankly, that is not really an improvement in the posts readability when you are using a news reader.
However, when requested, I will comply…

>> Hello,
>> I have a probem on a laptop I use, a MacBook Pro running openSUSE
>> Tumbleweed. I do not see this issue on any other system, also not on a
>> second MacBook. It is not a new problem, have seen that stuff for month
>> now, I never noticed any negative impact. However I cannot find out
>> where those messages come from in the system log file:
>> …]


>> Jul 23 14:45:30 balder pidof[7161]: can't read from 7173/stat
>> Jul 23 14:45:50 balder pidof[7526]: can't read from 7542/stat
>> Jul 23 14:46:42 balder pidof[8477]: can't read from 8415/stat
>> Jul 23 14:46:46 balder pidof[8540]: can't read from 8503/stat
>> Jul 23 14:47:02 balder pidof[8826]: can't read from 8828/stat
>> Jul 23 14:47:50 balder pidof[9667]: can't read from 9673/stat
>> Jul 23 14:47:54 balder pidof[9768]: can't read from 9748/stat
>> Jul 23 14:48:06 balder pidof[9969]: can't read from 9958/stat
>> Jul 23 14:49:54 balder pidof[11908]: can't read from 11902/stat
>> Jul 23 14:50:01 balder pidof[12052]: can't read from 12059/stat
>> ...]

I cannot even find out what type of process causes this, when the
message appears both the reading and the read process have already
gone.

Well, the process that causes that is “pidof”, which is been called by something else :slight_smile:
True, my question was indeed not really precise at that point :slight_smile:

It is not a kernel message. And I think it is trying to read from “/proc/PIDNUMBER/stat”, and
failing for some reason; perhaps the process in question has died by the time pidof is queried.
That is what I assumed.

If you get a lot of those, you can temporarily rename the pidof binary and see what complain
you get. Or block it with AA so that you get a report. If you want to try the AA route I’ll
post more details on that from my notes.
Good point.
I had a try and I am confused again about the result:

I made a trivial bash script meant to dump those calls to ‘pidof’ into a file, appending the name of the parent process of each call. My hope was to learn which application / process is the one actually doing the calls that fail. This would be a good starting point to find out what might be wrong. That script:


#!/bin/bash
parent=`ps -ocommand= -p $PPID | awk -F/ '{print $NF}' | awk '{print $1}'`
echo $parent >> /root/pidof-dump

I tested it by calling it directly from cli and verified that it indeed dumped the name of my calling shell into /root/pidof-dump. Next I checked where pidof is located. On my system it is located at two places: /bin/pidof and /sbin/pidof, both being symlinks to /sbin/killall5, as expected. I replaced the symlinks to point at my script and started tailing on a) the dump file and b) the system log file. As expected no more entries in the system log, however also no entries in the dump file. Hm. The moment I changed the links back again the entries in the system log started appearing again.

So I am just back where I started, unable to tell what process actually causes the entries.
Argh !

#9

On 2012-07-26 13:16, arkascha wrote:
>
> Hello,
> first of all: sorry for not using code tags. I thought it is not
> required in this case and frankly, that is not really an improvement in
> the posts readability when you are using a news reader.
> However, when requested, I will comply…

For nntp it avoids wrapping, but for web users it avoids conversions of certain combinations of
chars to others (like smileys). It is much safer to routinely use code tags to avoid problems.

In some case the formatting is so horrible that even on nntp it becomes impossible to interpret
outputs.


>   >> Jul 23 14:45:30 balder pidof[7161]: can't read from 7173/stat
>   >> Jul 23 14:45:50 balder pidof[7526]: can't read from 7542/stat
>   >> Jul 23 14:46:42 balder pidof[8477]: can't read from 8415/stat
>   >> Jul 23 14:46:46 balder pidof[8540]: can't read from 8503/stat
>   >> Jul 23 14:47:02 balder pidof[8826]: can't read from 8828/stat
>   >> Jul 23 14:47:50 balder pidof[9667]: can't read from 9673/stat
>   >> Jul 23 14:47:54 balder pidof[9768]: can't read from 9748/stat
>   >> Jul 23 14:48:06 balder pidof[9969]: can't read from 9958/stat
>   >> Jul 23 14:49:54 balder pidof[11908]: can't read from 11902/stat
>   >> Jul 23 14:50:01 balder pidof[12052]: can't read from 12059/stat
>   >> ...]
>

If you get a lot of those, you can temporarily rename the pidof binary and see what complain
you get. Or block it with AA so that you get a report. If you want to try the AA route I’ll
post more details on that from my notes.
Good point.
I had a try and I am confused again about the result:

I made a trivial bash script meant to dump those calls to ‘pidof’ into
a file, appending the name of the parent process of each call. My hope
was to learn which application / process is the one actually doing the
calls that fail. This would be a good starting point to find out what
might be wrong. That script:


>
>   #!/bin/bash
>   parent=`ps -ocommand= -p $PPID | awk -F/ '{print $NF}' | awk '{print $1}'`
>   echo $parent >> /root/pidof-dump

>
>
> I tested it by calling it directly from cli and verified that it indeed
> dumped the name of my calling shell into /root/pidof-dump. Next I
> checked where pidof is located. On my system it is located at two
> places: /bin/pidof and /sbin/pidof, both being symlinks to
> /sbin/killall5, as expected. I replaced the symlinks to point at my
> script and started tailing on a) the dump file and b) the system log
> file. As expected no more entries in the system log, however also no
> entries in the dump file. Hm. The moment I changed the links back again
> the entries in the system log started appearing again.

Curious.
Perhaps name your script “/sbin/killall5”, and add a call in your script in the last line to
“/usr/local/lib/killall5” (for instance) where you put the original binary. AH! Also, instead
of dumping the data in “/root/pidof-dump” do it in tmp, into a file writeable by all :slight_smile:

–
Cheers / Saludos,

Carlos E. R.
(from 11.4 x86_64 “Celadon” at Telcontar)

#10

Argh ! How obvious: your hint about the dump file not being writeable allowed me to get some output and dig deeper. I finally found the process causing the entries:
It is a plasmoid I use in my kde session, the service monitor. At start it spawns a shell and polls all services it is configured to monitor every few seconds. It was configured to monitor 8 services. Though these polls certainly are not expensive, the log file entries are certainly annoying. Although in general I think monitoring services is not such a bad idea I realize that 1) there are no problems with dying services here and 2) because of that I never really pay any notice to that monitoring… So away with it and all the entries have stopped.
I still don’t understand why there are so many processes that are obviously found in the process table apparently are gone moments later so that the stat call fails. This certainly happens now and then, for example if an apache child is terminated. But how often is that ?

Anyway, the question here about the “what” is solved.
Thanks for the assistance !

arkascha

#11

On 2012-07-29 07:56, arkascha wrote:

> Argh ! How obvious: your hint about the dump file not being writeable
> allowed me to get some output and dig deeper. I finally found the
> process causing the entries:
> It is a plasmoid I use in my kde session, the service monitor. At start
> it spawns a shell and polls all services it is configured to monitor
> every few seconds.

Aha! :slight_smile:

> It was configured to monitor 8 services. Though these
> polls certainly are not expensive, the log file entries are certainly
> annoying.

Indeed.

> Although in general I think monitoring services is not such a
> bad idea I realize that 1) there are no problems with dying services
> here and 2) because of that I never really pay any notice to that
> monitoring… So away with it and all the entries have stopped.
> I still don’t understand why there are so many processes that are
> obviously found in the process table apparently are gone moments later
> so that the stat call fails. This certainly happens now and then, for
> example if an apache child is terminated. But how often is that ?

Well, processes are started continuously, depending on what you have running and what the
system has. Notice the PID numbers going into several thousands.

For example, the “pidof” process is another process and it dies instantly itself.

That monitoring service is not really optimized to run continuously, it appears.

> Anyway, the question here about the “what” is solved.
> Thanks for the assistance !

Welcome :slight_smile:

–
Cheers / Saludos,

Carlos E. R.
(from 11.4 x86_64 “Celadon” at Telcontar)