- I have a long-running process (web proxy) that logs (verbosely) to syslog
- Something bad happens, and abrt steps in somehow
- The process continues to run...
- ...but all log messages to syslog are now tagged "abrt:" instead of "xfcproxy:"
- Any idea why?
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:" and at the bottom of this snippet under "abrt:"
Aug 27 07:02:55 proxy1 xfcproxy: uuid=63e63d9e connection=Open client_ip=192.168.3.21 client_port=40973 Aug 27 07:02:55 proxy1 xfcproxy: uuid=63e63d9e connection=Information method=CONNECT path=www.example.com port=443 Aug 27 07:02:55 proxy1 xfcproxy: 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: 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:
- 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.
- 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.
- 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.
- 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.