3

Short version:

  1. I have a long-running process (web proxy) that logs (verbosely) to syslog
  2. Something bad happens, and abrt steps in somehow
  3. The process continues to run...
  4. ...but all log messages to syslog are now tagged "abrt:" instead of "xfcproxy[1234]:"
  5. Any idea why?

Long version:

Here is an example of what we see from a log point of view, as "something happens" and the process continues to log but with the process name in syslog changing. Note how all messages from the proxy start "uuid=...", and we can see such messages logged at the top of this snippet under "xfcproxy[4808]:" and at the bottom of this snippet under "abrt:"

Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Open client_ip=192.168.3.21 client_port=40973
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:02:55 proxy1 xfcproxy[4808]: uuid=63e63d9e rule=Destination message="Match made" rule=monitoring uri=www.example.com
Aug 27 07:02:55 proxy1 rsyslogd-2177: imuxsock begins to drop messages from pid 4808 due to rate-limiting
Aug 27 07:02:55 proxy1 abrtd: New client connected
Aug 27 07:02:55 proxy1 abrtd: Directory 'pyhook-2014-08-27-07:02:55-4808' creation detected
Aug 27 07:02:55 proxy1 abrt-server[27032]: Saved Python crash dump of pid 4808 to /var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
Aug 27 07:02:55 proxy1 abrtd: Executable '/var/lib/xfcProxy/bin/xfcProxy.py' doesn't belong to any package and ProcessUnpackaged is set to 'no'
Aug 27 07:02:55 proxy1 abrtd: 'post-create' on '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808' exited with 1
Aug 27 07:02:55 proxy1 abrtd: Deleting problem directory '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'
Aug 27 07:03:37 proxy1 rsyslogd-2177: imuxsock lost 1642 messages from pid 4808 due to rate-limiting
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Open client_ip=192.168.3.21 client_port=40976
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 connection=Information method=CONNECT path=www.example.com port=443
Aug 27 07:03:37 proxy1 abrt: uuid=06bc7247 rule=Destination message="Match made" rule=monitoring uri=www.example.com

Using 'ps' I can see that the PID 4808 that had been running is still running:

[root@proxy1 log]# ps 4808
  PID TTY      STAT   TIME COMMAND
 4808 ?        S      1:34 python /var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 log]#

The 'imuxsock begins to drop messages' is somewhat normal - this daemon is very chatty (I've only shown a small sequential subset of messages here) and a flurry of messages can trigger rate limiting completely aside from this problem with rate limiting.

While my knowledge of abrt is limited, it doesn't seem to have crash info but does think that this process crashed correlated to the timing of the logs:

[root@proxy1 abrt]# pwd
/var/spool/abrt
[root@proxy1 abrt]# ls -l
total 4
-rw-r--r--. 1 root root  0 Mar 18 15:45 abrt-db
-rw-------  1 root root 33 Aug 27 07:02 last-via-server
[root@proxy1 abrt]# echo `cat last-via-server `
/var/lib/xfcProxy/bin/xfcProxy.py
[root@proxy1 abrt]#

The process in question is a multithreaded python process - I'm certainly open to the idea I'm not cleaning up threads properly and thus triggering this behavior. It's just odd behavior.

Clarifications for @Mikel:

  • Yes, RHEL 6
  • /var/log/messages via rsyslog. I haven't tried journald, and would need to reproduce on a non-production server before I could try a change like that.

Update following bounty period:

I'm afraid I cannot award the bounty for the existing answer by E Carter Young, for the following reasons:

  1. The imuxsock rate-limiting does not, so far as I can tell from reviewing rsyslog sources, trigger any sort of change to the process or involve abrtd in any way. It simply discards the flow for a little while, then resumes reading later.
  2. A process writing excessively to syslog is not in any way a buffer overflow situation. Resource utilization, yes; maybe even denial of service, but just because it's a buffer and just because it's very full doesn't mean it's a buffer overflow.
  3. The steps as described don't match the situation; specifically in step 6 rsyslog is not fetching from the abrt process, it's fetching from the original process; the mystery is why it's using abrt's name for that.
  4. I also am not convinced there's any race condition here. (Filling the log buffer fast is not a race condition)

I think this question is too complex and lacking data, and that it boils down to multiple simpler questions which could be asked with more data:

  • Why does abrtd trigger on a process that doesn't exit, if by definition it triggers on processes that crash? What represented enough of a crash to get abrtd involved? I think the answer lies in the missing logs, but I don't think the missing logs themselves are the answer. There's no evidence rsyslog invokes abrtd.
  • Why does rsyslog start using abrt as the process name once abrtd is triggered on a process (in a provable manner as answered by the previous question)?

Alas, without more data, I'm not comfortable pushing these questions today.

While I cannot accept this answer, I believe there's definitely value in it:

  • Description of the abrtd blacklist
  • Clear and concise discussion of my options
    • Increase or remove rate limit and clutter logs
    • Change process verbosity
    • blacklist process with abrt so that it never steps in

As such, I'm happy that half the bounty will go to E Carter Young's answer as the highest-voted answer when the bounty expires.

  • Assume you're on Fedora or RHEL? How are you printing syslog? Via /var/log/messages, journalctl, or some other way? Does each way give the same result? – Mikel Sep 3 '14 at 15:58
  • I need to see what's in Step 5 Below to shore this up. While I appreciate half the bounty, let me explain step 6. the abrtd daemon is looking for an exit status. The deleted file in step 5 would be included with that exit code, and abrtd would exit cleanly, but since the script continues running, you hang abrtd, which is why it prints in the log. – eyoung100 Sep 10 '14 at 15:59
2
+50

If you don't want this process handled by abrtd, add it to the abrtd blacklist in this conf file. Imuxsock is limiting the amount of logging because rate limiting is on. Once the limit is reached abrt will no longer log the real process name because it was told not to, therefore since the process is still running abrt shows as a replacement. See this blog. You may consider using Squid

Update
To understand this update section, you need to read up on Multiplexing, specifically:

In computer programming, it may refer to using a single in-memory resource (such as a file handle) to handle multiple external resources (such as on-disk files).


The file handle for your offending process is piped to this in memory resource. Under normal circumstances, most services and process for that matter have an exit code. Once the rate limit is reached, the immux socket transfers control to rsyslog to write the line:

imuxsock begins to drop messages from pid 4808 due to rate-limiting

At that point, abrt assumes that the offending process will have exited with an abnormal exit code, and writes the offending process and any output to /var/spool/abrt/pyhook-(time_date). Since your script has no exit code, at the next log write, rsyslog grabs whatever is in the imuxsocket buffer, but because the socket buffer never emptied - see step 5, because your process is still running, you create a buffer problem... Hackers commonly turn these situations into buffer overflows. These steps occur in the following order:

  1. Imuxsock reports to rsyslog that process 4808 shouldn't be reported.
  2. abrtd is configured to report any odd behavior, and starts
  3. rsyslog honors the request.
  4. Your script, under pid 4808 keeps writing to the log, reporting no exit code, because you designed it that way.
  5. abrtd realizing it cannot provide an exit code to rsyslog does the following(because your process doesn't quit):

Aug 27 07:02:55 proxy1 abrtd: Deleting problem directory '/var/spool/abrt/pyhook-2014-08-27-07:02:55-4808'

Had the exit code been reported, abrtd would send a bug report to you, if configured to do so. See the abrtd man page, and you would see the contents of /var/spool/abrt/pyhook-2014-08-27-07:02:55-4808
6. rsyslog, because it's honoring step 2, cannot report process 4808 fetches the most recent item in the imux buffer, which happens to be the abrt process, because abrt is still waiting on an exit code from step 5, but since step 5 never completed.....

In programming terms this is called a race condition. The program you wrote is filling the log buffer faster than the log buffer can write output. As such either:

  • set SysSock.RateLimit.Interval > 5 secs, and SysSock.RateLimit.Burst > 200
  • set SysSock.RateLimit.Interval = 0 and clutter your log.
  • rewrite your program with parameters to set the verbosity
  • run your script as a service and blacklist it in the abrtd configs
  • I don't think the uuid=... messages are actually being sent to abrt. – Mikel Sep 3 '14 at 16:01
  • They arent, I agree but the original process name is not used because the imux socket told rsyslog not to log that process anymore therefore abrt shows instead because the logging was "aborted" by abrt. Sorry if my answer wasn't clear. – eyoung100 Sep 3 '14 at 16:07
  • Can you clarify, are you saying that the act of lmuxsock reaching its rsyslogd rate limit is what triggers abrt to step in, not any intrinsic fault ("crash") of the xfcproxy program itself? That would be mildly insane ("Process foo logs badly... let's continue to log its messages under another name!"). Alas, Squid doesn't do what xfcProxy does (or vice versa). – gowenfawr Sep 3 '14 at 16:19
  • Yes that's what I'm saying... Because xfcProxy logs verbosely and rsyslogd was told not to log it because abrt told it not to, after reaching the imux limit, it logs as abrt because process 4808 in imux matches 4808 that's still running. Since abrt now has precedence thanks to imux, it logs as abrt. Can you tell me where you got xfcProxy? – eyoung100 Sep 3 '14 at 16:28
  • @gowenfawr If xfcProxy had really "crashed" syslog would log nothing at all, i.e you would see neither abrt or abrtd in the logs. Also, ps 4808 would return nothing – eyoung100 Sep 3 '14 at 16:43

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.