Re: [rsyslog] Updates 8.29 -> 8.30 broke several logs

2017-10-20 Thread Rainer Gerhards 
2017-10-20 15:20 GMT+02:00 Mike Schleif :
> Rainer,
>
> Attached is the debug log for the working rsyslog (8.29), delimited by
> reboots on both ends.
>
> NOTE: 4419.335959863 - boot complete
> 4720.680124293 - immediately after reboot Enter

OK, here we do not have the journal error. So I think that's the root
cause. We now need to find out what the journal error really is. To do
so, I asked Florian today to build a special package for you. You need
this repo:

[rsyslog_testing]
name=Adiscon CentOS-$releasever - Only for Testing Packages
baseurl=http://rpms.adiscon.com/testing/epel-$releasever/$basearch
enabled=1
gpgcheck=1
gpgkey=http://rpms.adiscon.com/RPM-GPG-KEY-Adiscon
protect=1

It contains rsyslog 8.30.0.1, which has a fix to make imjournal emit
the real error.

Please start it up under debug logging. It should fail as before but
emit a better error message.

>
> Regarding "error messages rsyslog emits" - I'm unclear about which messages
> you reference. Are you referring to /var/log/messages lines, such as
> following?
> Oct 20 07:57:02 hermes rsyslogd[21862]: -- MARK --

I guess you use OS default and the OS default is to throw them away :-(

Anyhow, you should see the messages inside the journal as well.
Assuming that the rsyslog service file is "rsyslog.service", you can
use the following command to get the data from the journal:
$ journalctl -u rsyslog.service

The status info also includes the last couple of messages:
$ systemctl status rsyslog.service

Let me know if that works for you. Please also provide me the debug
log with the special version we crafted for you.

Rainer
>
> ~ Mike
>
>
> On Fri, Oct 20, 2017 at 1:37 AM, Rainer Gerhards 
> wrote:
>
>> Mike,
>>
>> question: do you look at the error messages rsyslog emits? Or do you
>> throw them away (many distros do that by default)? I am asking because
>> I went through the debug log with the new information you gave. I see
>> these errors emitted by rsyslog's imjournal:
>> ```
>> 'imjournal: couldn't seek to cursor
>> `s=dec6d981bf5647a2b6b7970597e4471d;i=455;b=b05da23ccaf04159888a0615326154
>> 02;m=1337f528;t=55be6afe2d949;x=965813e66f54721f
>> sd_journal_next() failed: 'Success'
>> ```
>> The second one is strange and most probably the root cause of the
>> missing information.
>>
>> Will be very interested to see what the log with the older version shows.
>>
>> In general, I strongly suggest to have a look at rsyslog error
>> messages, these can considerably ease your life ;-)
>>
>> Rainer
>>
>> 2017-10-19 21:23 GMT+02:00 Rainer Gerhards :
>> > It would be great to have it as similar as possible.
>> >
>> > Sent from phone, thus brief.
>> >
>> > Am 19.10.2017 20:57 schrieb "Mike Schleif" > >:
>> >>
>> >> Rainer,
>> >>
>> >> Yes, I respect your time. Since it is running with 8.29, I can keep this
>> >> running as-is for a week or so; but, I do need the update fixes asap.
>> >>
>> >> For debug log from working system, do you need any system reboot?
>> >>
>> >> If not, I can turn on debug in rsyslog.conf, then simple restart
>> rsyslogd.
>> >>
>> >> Please, advise. Thank you.
>> >>
>> >> ~ Mike
>> >>
>> >>
>> >>
>> >> On Thu, Oct 19, 2017 at 1:35 PM, Rainer Gerhards
>> >> 
>> >> wrote:
>> >>
>> >> > I think David can probably answer that better. You need to check
>> systemd
>> >> > and journal conf.
>> >> >
>> >> > But you said it works with an older version. Can you create a Debug
>> log
>> >> > with that one as well so that I can compare? That would probably be
>> >> > useful.
>> >> > Again (due to time zone differences) I can look at this at earliest in
>> >> > roughly 12 hours - depending on what work has waiting for me in the
>> >> > morning. Having both logs by then would definitely be a plus.
>> >> >
>> >> > Rainer
>> >> >
>> >> > Sent from phone, thus brief.
>> >> >
>> >> > Am 19.10.2017 20:24 schrieb "Mike Schleif"
>> >> > :
>> >> >
>> >> > > Rainer,
>> >> > >
>> >> > > Apparently, I wasn't explicit enough when submitting the debug log.
>> >> > >
>> >> > > You asked: Did something (systemd) steal the log socket?
>> >> > >
>> >> > > I don't know. How could I know? How can I find out?
>> >> > >
>> >> > > Please, advise. Thank you.
>> >> > >
>> >> > > ~ Mike
>> >> > >
>> >> > >
>> >> > > On Thu, Oct 19, 2017 at 1:18 PM, Rainer Gerhards <
>> >> > rgerha...@hq.adiscon.com
>> >> > > >
>> >> > > wrote:
>> >> > >
>> >> > > > Well it would have helped to have this information before wading
>> >> > through
>> >> > > > the log ;-). Now it needs to wait till tomorrow or Monday.
>> >> > > >
>> >> > > > Did something (systemd) steal the log socket?
>> >> > > >
>> >> > > > Räuber
>> >> > > >
>> >> > > > Sent from phone, thus brief.
>> >> > > >
>> >> > > > Am 19.10.2017 19:53 schrieb "Mike Schleif" <
>> >> > mike+rsys...@mdsresource.net
>> >> > > >:
>> >> > > >
>> >>

[rsyslog] Fwd: Your message to rsyslog awaits moderator approval

2017-10-20 Thread Mike Schleif 
Rainer,

Please, moderate my debug containing message below:


-- Forwarded message --
From: 
Date: Fri, Oct 20, 2017 at 8:20 AM
Subject: Your message to rsyslog awaits moderator approval
To: mike+rsys...@mdsresource.net


Your mail to 'rsyslog' with the subject

Re: [rsyslog] Updates 8.29 -> 8.30 broke several logs

Is being held until the list moderator can review it for approval.

The reason it is being held:

Message body is too big: 1667478 bytes with a limit of 768 KB

Either the message will get posted to the list, or you will receive
notification of the moderator's decision.  If you would like to cancel
this posting, please visit the following URL:

http://lists.adiscon.net/mailman/confirm/rsyslog/
405ada4cf933eac27a3f5ee833b8ccea9b5420c8
___
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of 
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE 
THAT.

Re: [rsyslog] Updates 8.29 -> 8.30 broke several logs

2017-10-20 Thread Mike Schleif 
Earlier this year, I posted about our problem with this host, and delayed
writes to Mysql databases. I noted, at that time, this imjournal error, as
well as intermittent cached files in WorkDirectory for these ommysql queues.

After initial queries from the list, I answered, and received no answers.
We continues to struggle with fifteen (15) minute db write delays
periodically throughout the day.

Interestingly enough, yesterday and today, after boot up, the queue files
are there again:

# ls -alrt /var/lib/rsyslog/
total 840
drwxr-xr-x. 34 root root   4096 Oct  3 11:30 ..
-rw---   1 root root 406707 Oct 20 08:06 ZenossQueue.0001
-rw---   1 root root 442098 Oct 20 08:06 SIEMQueue.0001
-rw---   1 root root121 Oct 20 08:17 imjournal.state
drwx--.  2 root root 80 Oct 20 08:17 .

# /bin/systemctl restart rsyslog

# ls -alrt /var/lib/rsyslog/
total 8
drwxr-xr-x. 34 root root 4096 Oct  3 11:30 ..
-rw---   1 root root  121 Oct 20 08:17 imjournal.state
drwx--.  2 root root   28 Oct 20 08:17 .


Please, advise. Thank you.

~ Mike



On Fri, Oct 20, 2017 at 1:37 AM, Rainer Gerhards 
wrote:

> Mike,
>
> question: do you look at the error messages rsyslog emits? Or do you
> throw them away (many distros do that by default)? I am asking because
> I went through the debug log with the new information you gave. I see
> these errors emitted by rsyslog's imjournal:
> ```
> 'imjournal: couldn't seek to cursor
> `s=dec6d981bf5647a2b6b7970597e4471d;i=455;b=b05da23ccaf04159888a0615326154
> 02;m=1337f528;t=55be6afe2d949;x=965813e66f54721f
> sd_journal_next() failed: 'Success'
> ```
> The second one is strange and most probably the root cause of the
> missing information.
>
> Will be very interested to see what the log with the older version shows.
>
> In general, I strongly suggest to have a look at rsyslog error
> messages, these can considerably ease your life ;-)
>
> Rainer
>
> 2017-10-19 21:23 GMT+02:00 Rainer Gerhards :
> > It would be great to have it as similar as possible.
> >
> > Sent from phone, thus brief.
> >
> > Am 19.10.2017 20:57 schrieb "Mike Schleif"  >:
> >>
> >> Rainer,
> >>
> >> Yes, I respect your time. Since it is running with 8.29, I can keep this
> >> running as-is for a week or so; but, I do need the update fixes asap.
> >>
> >> For debug log from working system, do you need any system reboot?
> >>
> >> If not, I can turn on debug in rsyslog.conf, then simple restart
> rsyslogd.
> >>
> >> Please, advise. Thank you.
> >>
> >> ~ Mike
> >>
> >>
> >>
> >> On Thu, Oct 19, 2017 at 1:35 PM, Rainer Gerhards
> >> 
> >> wrote:
> >>
> >> > I think David can probably answer that better. You need to check
> systemd
> >> > and journal conf.
> >> >
> >> > But you said it works with an older version. Can you create a Debug
> log
> >> > with that one as well so that I can compare? That would probably be
> >> > useful.
> >> > Again (due to time zone differences) I can look at this at earliest in
> >> > roughly 12 hours - depending on what work has waiting for me in the
> >> > morning. Having both logs by then would definitely be a plus.
> >> >
> >> > Rainer
> >> >
> >> > Sent from phone, thus brief.
> >> >
> >> > Am 19.10.2017 20:24 schrieb "Mike Schleif"
> >> > :
> >> >
> >> > > Rainer,
> >> > >
> >> > > Apparently, I wasn't explicit enough when submitting the debug log.
> >> > >
> >> > > You asked: Did something (systemd) steal the log socket?
> >> > >
> >> > > I don't know. How could I know? How can I find out?
> >> > >
> >> > > Please, advise. Thank you.
> >> > >
> >> > > ~ Mike
> >> > >
> >> > >
> >> > > On Thu, Oct 19, 2017 at 1:18 PM, Rainer Gerhards <
> >> > rgerha...@hq.adiscon.com
> >> > > >
> >> > > wrote:
> >> > >
> >> > > > Well it would have helped to have this information before wading
> >> > through
> >> > > > the log ;-). Now it needs to wait till tomorrow or Monday.
> >> > > >
> >> > > > Did something (systemd) steal the log socket?
> >> > > >
> >> > > > Räuber
> >> > > >
> >> > > > Sent from phone, thus brief.
> >> > > >
> >> > > > Am 19.10.2017 19:53 schrieb "Mike Schleif" <
> >> > mike+rsys...@mdsresource.net
> >> > > >:
> >> > > >
> >> > > > > Look at line: 32697 - That is the LAST line of debug as the
> system
> >> > > booted
> >> > > > > up.
> >> > > > >
> >> > > > > Now, look at the next line: 32698 - That is the first line after
> >> > > > > the
> >> > > > > sysadmin pressed Enter after typing "reboot."
> >> > > > >
> >> > > > > I don't understand the time encoding prior to the first colon
> (:)
> >> > > > > of
> >> > > each
> >> > > > > line; but, this host was up for ten (10) minutes or more before
> >> > backing
> >> > > > out
> >> > > > > of the update patches and reboot.
> >> > > > >
> >> > > > > How can I provide missing messages, when they are missing?
> >> > > > >
> >> > > > > The only way to get to this host

Re: [rsyslog] Updates 8.29 -> 8.30 broke several logs

2017-10-20 Thread Rainer Gerhards 
FYI: created https://github.com/rsyslog/rsyslog/issues/1867

2017-10-20 8:37 GMT+02:00 Rainer Gerhards :
> Mike,
>
> question: do you look at the error messages rsyslog emits? Or do you
> throw them away (many distros do that by default)? I am asking because
> I went through the debug log with the new information you gave. I see
> these errors emitted by rsyslog's imjournal:
> ```
> 'imjournal: couldn't seek to cursor
> `s=dec6d981bf5647a2b6b7970597e4471d;i=455;b=b05da23ccaf04159888a061532615402;m=1337f528;t=55be6afe2d949;x=965813e66f54721f
> sd_journal_next() failed: 'Success'
> ```
> The second one is strange and most probably the root cause of the
> missing information.
>
> Will be very interested to see what the log with the older version shows.
>
> In general, I strongly suggest to have a look at rsyslog error
> messages, these can considerably ease your life ;-)
>
> Rainer
>
> 2017-10-19 21:23 GMT+02:00 Rainer Gerhards :
>> It would be great to have it as similar as possible.
>>
>> Sent from phone, thus brief.
>>
>> Am 19.10.2017 20:57 schrieb "Mike Schleif" :
>>>
>>> Rainer,
>>>
>>> Yes, I respect your time. Since it is running with 8.29, I can keep this
>>> running as-is for a week or so; but, I do need the update fixes asap.
>>>
>>> For debug log from working system, do you need any system reboot?
>>>
>>> If not, I can turn on debug in rsyslog.conf, then simple restart rsyslogd.
>>>
>>> Please, advise. Thank you.
>>>
>>> ~ Mike
>>>
>>>
>>>
>>> On Thu, Oct 19, 2017 at 1:35 PM, Rainer Gerhards
>>> 
>>> wrote:
>>>
>>> > I think David can probably answer that better. You need to check systemd
>>> > and journal conf.
>>> >
>>> > But you said it works with an older version. Can you create a Debug log
>>> > with that one as well so that I can compare? That would probably be
>>> > useful.
>>> > Again (due to time zone differences) I can look at this at earliest in
>>> > roughly 12 hours - depending on what work has waiting for me in the
>>> > morning. Having both logs by then would definitely be a plus.
>>> >
>>> > Rainer
>>> >
>>> > Sent from phone, thus brief.
>>> >
>>> > Am 19.10.2017 20:24 schrieb "Mike Schleif"
>>> > :
>>> >
>>> > > Rainer,
>>> > >
>>> > > Apparently, I wasn't explicit enough when submitting the debug log.
>>> > >
>>> > > You asked: Did something (systemd) steal the log socket?
>>> > >
>>> > > I don't know. How could I know? How can I find out?
>>> > >
>>> > > Please, advise. Thank you.
>>> > >
>>> > > ~ Mike
>>> > >
>>> > >
>>> > > On Thu, Oct 19, 2017 at 1:18 PM, Rainer Gerhards <
>>> > rgerha...@hq.adiscon.com
>>> > > >
>>> > > wrote:
>>> > >
>>> > > > Well it would have helped to have this information before wading
>>> > through
>>> > > > the log ;-). Now it needs to wait till tomorrow or Monday.
>>> > > >
>>> > > > Did something (systemd) steal the log socket?
>>> > > >
>>> > > > Räuber
>>> > > >
>>> > > > Sent from phone, thus brief.
>>> > > >
>>> > > > Am 19.10.2017 19:53 schrieb "Mike Schleif" <
>>> > mike+rsys...@mdsresource.net
>>> > > >:
>>> > > >
>>> > > > > Look at line: 32697 - That is the LAST line of debug as the system
>>> > > booted
>>> > > > > up.
>>> > > > >
>>> > > > > Now, look at the next line: 32698 - That is the first line after
>>> > > > > the
>>> > > > > sysadmin pressed Enter after typing "reboot."
>>> > > > >
>>> > > > > I don't understand the time encoding prior to the first colon (:)
>>> > > > > of
>>> > > each
>>> > > > > line; but, this host was up for ten (10) minutes or more before
>>> > backing
>>> > > > out
>>> > > > > of the update patches and reboot.
>>> > > > >
>>> > > > > How can I provide missing messages, when they are missing?
>>> > > > >
>>> > > > > The only way to get to this host is via SSH. During the period of
>>> > > > > the
>>> > > > debug
>>> > > > > log, another sysadmin and I logged onto that host at least three
>>> > > > > (3)
>>> > > > times
>>> > > > > each - not one write to /var/log/secure !?!?
>>> > > > >
>>> > > > > Yes, there are /var/log/* writes up until the system fully booted
>>> > > > > -
>>> > > then
>>> > > > > nothing - until sysadmin pressed Enter, more than ten (10) minutes
>>> > > later.
>>> > > > > The ONLY /var/log/ files to get written to during that period were
>>> > > > > /var/log/lastlog and /var/log/wtmp - NOT one other log was written
>>> > > > > to
>>> > > in
>>> > > > > more than ten (10) minutes ...
>>> > > > >
>>> > > > > Please, advise. Thank you.
>>> > > > >
>>> > > > > ~ Mike
>>> > > > >
>>> > > > >
>>> > > > >
>>> > > > > On Thu, Oct 19, 2017 at 12:32 PM, Rainer Gerhards <
>>> > > > > rgerha...@hq.adiscon.com>
>>> > > > > wrote:
>>> > > > >
>>> > > > > > 2017-10-19 16:14 GMT+02:00 Mike Schleif <
>>> > > mike+rsys...@mdsresource.net>
>>> > > > :
>>> > > > > > > Rainer,
>>> > > > > > >
>>> > > > > > > Debug attached. Full reboot follows each update and roll

Re: [rsyslog] Updates 8.29 -> 8.30 broke several logs

2017-10-20 Thread Rainer Gerhards 
Mike,

question: do you look at the error messages rsyslog emits? Or do you
throw them away (many distros do that by default)? I am asking because
I went through the debug log with the new information you gave. I see
these errors emitted by rsyslog's imjournal:
```
'imjournal: couldn't seek to cursor
`s=dec6d981bf5647a2b6b7970597e4471d;i=455;b=b05da23ccaf04159888a061532615402;m=1337f528;t=55be6afe2d949;x=965813e66f54721f
sd_journal_next() failed: 'Success'
```
The second one is strange and most probably the root cause of the
missing information.

Will be very interested to see what the log with the older version shows.

In general, I strongly suggest to have a look at rsyslog error
messages, these can considerably ease your life ;-)

Rainer

2017-10-19 21:23 GMT+02:00 Rainer Gerhards :
> It would be great to have it as similar as possible.
>
> Sent from phone, thus brief.
>
> Am 19.10.2017 20:57 schrieb "Mike Schleif" :
>>
>> Rainer,
>>
>> Yes, I respect your time. Since it is running with 8.29, I can keep this
>> running as-is for a week or so; but, I do need the update fixes asap.
>>
>> For debug log from working system, do you need any system reboot?
>>
>> If not, I can turn on debug in rsyslog.conf, then simple restart rsyslogd.
>>
>> Please, advise. Thank you.
>>
>> ~ Mike
>>
>>
>>
>> On Thu, Oct 19, 2017 at 1:35 PM, Rainer Gerhards
>> 
>> wrote:
>>
>> > I think David can probably answer that better. You need to check systemd
>> > and journal conf.
>> >
>> > But you said it works with an older version. Can you create a Debug log
>> > with that one as well so that I can compare? That would probably be
>> > useful.
>> > Again (due to time zone differences) I can look at this at earliest in
>> > roughly 12 hours - depending on what work has waiting for me in the
>> > morning. Having both logs by then would definitely be a plus.
>> >
>> > Rainer
>> >
>> > Sent from phone, thus brief.
>> >
>> > Am 19.10.2017 20:24 schrieb "Mike Schleif"
>> > :
>> >
>> > > Rainer,
>> > >
>> > > Apparently, I wasn't explicit enough when submitting the debug log.
>> > >
>> > > You asked: Did something (systemd) steal the log socket?
>> > >
>> > > I don't know. How could I know? How can I find out?
>> > >
>> > > Please, advise. Thank you.
>> > >
>> > > ~ Mike
>> > >
>> > >
>> > > On Thu, Oct 19, 2017 at 1:18 PM, Rainer Gerhards <
>> > rgerha...@hq.adiscon.com
>> > > >
>> > > wrote:
>> > >
>> > > > Well it would have helped to have this information before wading
>> > through
>> > > > the log ;-). Now it needs to wait till tomorrow or Monday.
>> > > >
>> > > > Did something (systemd) steal the log socket?
>> > > >
>> > > > Räuber
>> > > >
>> > > > Sent from phone, thus brief.
>> > > >
>> > > > Am 19.10.2017 19:53 schrieb "Mike Schleif" <
>> > mike+rsys...@mdsresource.net
>> > > >:
>> > > >
>> > > > > Look at line: 32697 - That is the LAST line of debug as the system
>> > > booted
>> > > > > up.
>> > > > >
>> > > > > Now, look at the next line: 32698 - That is the first line after
>> > > > > the
>> > > > > sysadmin pressed Enter after typing "reboot."
>> > > > >
>> > > > > I don't understand the time encoding prior to the first colon (:)
>> > > > > of
>> > > each
>> > > > > line; but, this host was up for ten (10) minutes or more before
>> > backing
>> > > > out
>> > > > > of the update patches and reboot.
>> > > > >
>> > > > > How can I provide missing messages, when they are missing?
>> > > > >
>> > > > > The only way to get to this host is via SSH. During the period of
>> > > > > the
>> > > > debug
>> > > > > log, another sysadmin and I logged onto that host at least three
>> > > > > (3)
>> > > > times
>> > > > > each - not one write to /var/log/secure !?!?
>> > > > >
>> > > > > Yes, there are /var/log/* writes up until the system fully booted
>> > > > > -
>> > > then
>> > > > > nothing - until sysadmin pressed Enter, more than ten (10) minutes
>> > > later.
>> > > > > The ONLY /var/log/ files to get written to during that period were
>> > > > > /var/log/lastlog and /var/log/wtmp - NOT one other log was written
>> > > > > to
>> > > in
>> > > > > more than ten (10) minutes ...
>> > > > >
>> > > > > Please, advise. Thank you.
>> > > > >
>> > > > > ~ Mike
>> > > > >
>> > > > >
>> > > > >
>> > > > > On Thu, Oct 19, 2017 at 12:32 PM, Rainer Gerhards <
>> > > > > rgerha...@hq.adiscon.com>
>> > > > > wrote:
>> > > > >
>> > > > > > 2017-10-19 16:14 GMT+02:00 Mike Schleif <
>> > > mike+rsys...@mdsresource.net>
>> > > > :
>> > > > > > > Rainer,
>> > > > > > >
>> > > > > > > Debug attached. Full reboot follows each update and roll back.
>> > > > > > >
>> > > > > > > It looks like nothing under /var/log/ gets written to after
>> > reboot
>> > > > > > > complete, except lastlog and wtmp.
>> > > > > >
>> > > > > > mmhhh... I see at least writes to
>> > > > > >
>> > > > > > /var/log/messages:
>> > > > > > Reg/w0  : strm