syslog-ng appending ancient info to logs
by rnturn from LinuxQuestions.org on (#55JJN)
Config: Tumbleweed (up-to-date as of 2020-07-05), systemd logging redirected to syslog-ng (i.e., systemd-logger not installed)
Situation: most log files in /var/log are being appended to using very old data. Running "tail -f" on most files shows information being added from months and months ago.
We had a power failure last night and this morning, after recovering from the mess that the storm created, I fired up an email monitoring command that shows messages that have been rejected by postfix. What immediately got my attention was that messages were scrolling by faster than I could read them and after hitting ^S I could see that the time stamps were nowhere near today's date. Manually issuing the "grep" command that searches for the rejects returned a "binary file matches" type message. Binary file? /var/log/mail? I figured corruption due to the power outage so I shut down postfix, renamed the mail* log files, touched new ones, and restarted postfix. Tailing /var/log/mail shows the same ancient data being added to the log file. Within minutes the log file had gotten up to 75MB. Conclusion: postfix is not the problem.
Turning my attention to /var/log/messages, I found that something very similar was happening: /var/log/messages had ancient data being added to it. The giveaway: "tail messages" should not be listing events from "Oct 17" on "Jul 10". The size of messages was also growing at a crazy rate, as well. Deep within the messages files was this:
Code:Jul 10 08:02:24 klaatu systemd[1]: Startup finished in 3.313s (kernel) + 4.295s
(initrd) + 2min 43.070s (userspace) = 2min 50.679s.
Jul 10 08:07:22 klaatu syslog-ng[1877]: syslog-ng starting up; version='3.26.1'
Sep 2 07:00:01 klaatu systemd[1]: Started Timeline of Snapper Snapshots.
Sep 2 07:00:01 klaatu dbus-daemon[1184]: [system] Activating service name='org.
opensuse.Snapper' requested by ':1.299' (uid=0 pid=25520 comm="/usr/lib/snapper/
systemd-helper --timeline ") (using servicehelper)
Sep 2 07:00:01 klaatu dbus-daemon[1184]: [system] Successfully activated servic
e 'org.opensuse.Snapper'The 8:07 record is from today's restart. That "Sep 2" is from 2018. ("Let's do the Time Warp")
To see how old the information is that's being (re)logged, I set "ts-format(iso)" (my preferred date/time format, anyway) in the syslog-ng config and restarted it. That "latest" information being added to /var/log/mail is from November 2019 at the time I'm (or was) typing this.
I thought that I might have fixed things by shutting down the two services, removing all the mail files and messages, and touching new ones. Unfortunately, as soon as I restarted syslog-ng, all these log files started filling up... and rapidly. (This time beginning from February 2020.) As I've been composing this, the logs appear to have gotten "caught up" now.
After doing a little more reading about journalctl, I ran "journalctl --verify" and it indicated that one of the logging files contains a corrupted entry. I can read that file using "journalctl --file="log-file-name" | head" and ".. | tail" and it appears to contain records from about a year ago. IMHO, safe to delete---as well as any earlier files. I'd be surprised if a journal/log file from a year ago would have anything to do with today's log file strangeness.
My working theory is: systemd somehow forgot where it was in the space-time continuum, threw up its hands, and decided to send everything it's ever logged to syslog-ng. Is it fixed now? Who knows? Tonight's mail activity report is going to be entertaining but that report will correct itself once the log files rotate.
Questions:
Situation: most log files in /var/log are being appended to using very old data. Running "tail -f" on most files shows information being added from months and months ago.
We had a power failure last night and this morning, after recovering from the mess that the storm created, I fired up an email monitoring command that shows messages that have been rejected by postfix. What immediately got my attention was that messages were scrolling by faster than I could read them and after hitting ^S I could see that the time stamps were nowhere near today's date. Manually issuing the "grep" command that searches for the rejects returned a "binary file matches" type message. Binary file? /var/log/mail? I figured corruption due to the power outage so I shut down postfix, renamed the mail* log files, touched new ones, and restarted postfix. Tailing /var/log/mail shows the same ancient data being added to the log file. Within minutes the log file had gotten up to 75MB. Conclusion: postfix is not the problem.
Turning my attention to /var/log/messages, I found that something very similar was happening: /var/log/messages had ancient data being added to it. The giveaway: "tail messages" should not be listing events from "Oct 17" on "Jul 10". The size of messages was also growing at a crazy rate, as well. Deep within the messages files was this:
Code:Jul 10 08:02:24 klaatu systemd[1]: Startup finished in 3.313s (kernel) + 4.295s
(initrd) + 2min 43.070s (userspace) = 2min 50.679s.
Jul 10 08:07:22 klaatu syslog-ng[1877]: syslog-ng starting up; version='3.26.1'
Sep 2 07:00:01 klaatu systemd[1]: Started Timeline of Snapper Snapshots.
Sep 2 07:00:01 klaatu dbus-daemon[1184]: [system] Activating service name='org.
opensuse.Snapper' requested by ':1.299' (uid=0 pid=25520 comm="/usr/lib/snapper/
systemd-helper --timeline ") (using servicehelper)
Sep 2 07:00:01 klaatu dbus-daemon[1184]: [system] Successfully activated servic
e 'org.opensuse.Snapper'The 8:07 record is from today's restart. That "Sep 2" is from 2018. ("Let's do the Time Warp")
To see how old the information is that's being (re)logged, I set "ts-format(iso)" (my preferred date/time format, anyway) in the syslog-ng config and restarted it. That "latest" information being added to /var/log/mail is from November 2019 at the time I'm (or was) typing this.
I thought that I might have fixed things by shutting down the two services, removing all the mail files and messages, and touching new ones. Unfortunately, as soon as I restarted syslog-ng, all these log files started filling up... and rapidly. (This time beginning from February 2020.) As I've been composing this, the logs appear to have gotten "caught up" now.
After doing a little more reading about journalctl, I ran "journalctl --verify" and it indicated that one of the logging files contains a corrupted entry. I can read that file using "journalctl --file="log-file-name" | head" and ".. | tail" and it appears to contain records from about a year ago. IMHO, safe to delete---as well as any earlier files. I'd be surprised if a journal/log file from a year ago would have anything to do with today's log file strangeness.
My working theory is: systemd somehow forgot where it was in the space-time continuum, threw up its hands, and decided to send everything it's ever logged to syslog-ng. Is it fixed now? Who knows? Tonight's mail activity report is going to be entertaining but that report will correct itself once the log files rotate.
Questions:
- Has anyone else experienced this type of logging problem?
- Am I correct in assuming that something like "journal --vacuum-time=1y" will do the cleanup I'm hoping will limit any of the crazy "re-syslogging" to events no older than that "1y" time span? (In case systemd's logger goes off the deep and again.)