Bug#839804: monit: errors every 2 minutes in the log file: "Queued event file: unable to read event size -- end of file"

[Vincent Lefevre]

Package: monit
Version: 1:5.19.0-1
Severity: normal

Here's the beginning or my /var/log/monit.log.1 file:

[CEST Sep 9 07:35:07] info : 'zira' Monit reloaded
[CEST Sep 9 07:35:07] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:09:34] info : Monit daemon with pid [793] stopped
[CEST Sep 19 19:09:34] info : 'zira' Monit 5.19.0 stopped
[CEST Sep 19 19:09:34] error : Cannot create socket to [localhost]:25 -- Connection refused
[CEST Sep 19 19:09:34] error : Cannot open a connection to the mailserver localhost:25 -- Operation now in progress
[CEST Sep 19 19:09:34] error : Mail: Delivery failed -- no mail server is available
[CEST Sep 19 19:09:34] info : Adding event to the queue file /var/lib/monit/events/1474304974_8cf8f0 for later delivery
[CEST Sep 19 19:10:11] info : Starting Monit 5.19.0 daemon
[CEST Sep 19 19:10:11] info : 'zira' Monit 5.19.0 started
[CEST Sep 19 19:10:11] error : Cannot create socket to [localhost]:25 -- Connection refused
[CEST Sep 19 19:10:11] error : Cannot open a connection to the mailserver localhost:25 -- Operation now in progress
[CEST Sep 19 19:10:11] error : Mail: Delivery failed -- no mail server is available
[CEST Sep 19 19:10:11] info : Adding event to the queue file /var/lib/monit/events/1474305011_1babb20 for later delivery
[CEST Sep 19 19:10:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:10:11] error : Cannot create socket to [localhost]:25 -- Connection refused
[CEST Sep 19 19:10:11] error : Cannot open a connection to the mailserver localhost:25 -- Operation now in progress
[CEST Sep 19 19:10:11] error : Mail: Delivery failed -- no mail server is available
[CEST Sep 19 19:10:11] error : Alert handler failed, retry scheduled for next cycle
[CEST Sep 19 19:10:11] error : 'eth0' link down
[CEST Sep 19 19:10:11] error : Cannot create socket to [localhost]:25 -- Connection refused
[CEST Sep 19 19:10:11] error : Cannot open a connection to the mailserver localhost:25 -- Operation now in progress
[CEST Sep 19 19:10:11] error : Mail: Delivery failed -- no mail server is available
[CEST Sep 19 19:10:11] info : Adding event to the queue file /var/lib/monit/events/1474305011_1bbbd00 for later delivery
[CEST Sep 19 19:12:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:12:11] info : 'eth0' link up
[CEST Sep 19 19:14:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:16:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:18:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:20:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:22:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:24:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:26:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:28:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:30:11] error : Queued event file: unable to read event size -- end of file
[CEST Sep 19 19:32:11] error : Queued event file: unable to read event size -- end of file
[...]

At reload, everything is fine. Then one gets some errors during a reboot
as Monit cannot connect to the mailserver at this time, which is normal
since the mail server has been stopped before Monit. This is not a
problem, as I will receive the mail after the reboot. The problem is
the "Queued event file: unable to read event size -- end of file" errors
every 2 minutes after the reboot, which fill my log file.

This may be a long-standing bug, which I hadn't noticed until now.

In my monitrc file, I have in particular:

set mailserver localhost
set alert vin...@vinc17.net

-- Package-specific info:

Monit config file /etc/monit/monitrc is *NOT* readable by reportbug.
Please, consider to rerun reportbug as root and *carefully* examine
reportbug's output (e.g., monitrc content), before sending it out.

Contents of /etc/monit/ directory:
/etc/monit:
total 32
drwxr-xr-x 2 root root 4096 2016-08-09 01:02:40 conf-available
drwxr-xr-x 2 root root 4096 2015-12-05 21:19:30 conf-enabled
drwxr-xr-x 2 root root 4096 2015-07-07 14:43:58 conf.d
-rw------- 1 root root 12176 2016-08-09 01:19:28 monitrc
drwxr-xr-x 2 root root 4096 2016-07-15 19:34:40 monitrc.d
drwxr-xr-x 2 root root 4096 2016-08-09 01:06:27 templates

/etc/monit/conf-available:
total 60
-rw-r--r-- 1 root root 481 2015-12-05 21:13:49 acpid
-rw-r--r-- 1 root root 640 2015-12-05 21:13:49 apache2
-rw-r--r-- 1 root root 455 2015-12-05 21:13:49 at
-rw-r--r-- 1 root root 691 2015-12-05 21:13:49 cron
-rw-r--r-- 1 root root 602 2015-12-05 21:13:49 mdadm
-rw-r--r-- 1 root root 669 2015-12-05 21:13:49 memcached
-rw-r--r-- 1 root root 703 2015-12-05 21:13:49 mysql
-rw-r--r-- 1 root root 521 2015-12-05 21:13:49 nginx
-rw-r--r-- 1 root root 471 2015-12-05 21:13:49 openntpd
-rw-r--r-- 1 root root 950 2015-12-05 21:13:49 openssh-server
-rw-r--r-- 1 root root 683 2015-12-05 21:13:49 pdns-recursor
-rw-r--r-- 1 root root 1421 2015-12-05 21:13:49 postfix
-rw-r--r-- 1 root root 869 2016-03-22 16:43:44 rsyslog
-rw-r--r-- 1 root root 501 2015-12-05 21:13:49 smartmontools
-rw-r--r-- 1 root root 306 2016-02-04 15:03:50 snmpd

/etc/monit/conf-enabled:
total 0

/etc/monit/conf.d:
total 4
-rw-r--r-- 1 root root 357 2015-07-07 14:43:58 eth0

/etc/monit/monitrc.d:
total 64
-rw-r--r-- 1 root root 481 2015-06-09 15:52:48 acpid
-rw-r--r-- 1 root root 640 2015-06-09 15:52:48 apache2
-rw-r--r-- 1 root root 455 2015-06-09 15:52:48 at
-rw-r--r-- 1 root root 691 2015-06-09 15:52:48 cron
-rw-r--r-- 1 root root 408 2015-04-29 06:12:16 fail2ban
-rw-r--r-- 1 root root 602 2015-06-09 15:52:48 mdadm
-rw-r--r-- 1 root root 669 2015-06-09 15:52:48 memcached
-rw-r--r-- 1 root root 703 2015-06-09 15:52:48 mysql
-rw-r--r-- 1 root root 521 2015-06-09 15:52:48 nginx
-rw-r--r-- 1 root root 471 2015-06-09 15:52:48 openntpd
-rw-r--r-- 1 root root 950 2015-06-09 15:52:48 openssh-server
-rw-r--r-- 1 root root 683 2015-06-09 15:52:48 pdns-recursor
-rw-r--r-- 1 root root 1421 2015-06-09 15:52:48 postfix
-rw-r--r-- 1 root root 867 2015-06-09 15:52:48 rsyslog
-rw-r--r-- 1 root root 501 2015-06-09 15:52:48 smartmontools
-rw-r--r-- 1 root root 310 2015-06-09 15:52:48 snmpd

/etc/monit/templates:
total 12
-rw-r--r-- 1 root root 164 2015-06-09 15:52:48 rootbin
-rw-r--r-- 1 root root 160 2015-06-09 15:52:48 rootrc
-rw-r--r-- 1 root root 164 2015-06-09 15:52:48 rootstrict


-- System Information:
Debian Release: stretch/sid
APT prefers unstable-debug
APT policy: (500, 'unstable-debug'), (500, 'stable-updates'), (500, 'unstable'), (500, 'testing'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 4.7.0-1-amd64 (SMP w/8 CPU cores)
Locale: LANG=POSIX, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages monit depends on:
ii libc6 2.24-3
ii libpam0g 1.1.8-3.3
ii libssl1.0.2 1.0.2j-1
ii lsb-base 9.20160629

monit recommends no packages.

Versions of packages monit suggests:
ii postfix [mail-transport-agent] 3.1.0-5+b1
pn sysvinit-core <none>

-- Configuration Files:
/etc/monit/monitrc [Errno 13] Permission denied: u'/etc/monit/monitrc'

-- no debconf information

[Sergey Kirpichev]

tag 839804 +moreinfo
thanks

Hello,

On Wed, Oct 5, 2016 at 12:09 PM, Vincent Lefevre <vin...@vinc17.net> wrote:
> [CEST Sep 19 19:10:11] info : Adding event to the queue file /var/lib/monit/events/1474305011_1bbbd00 for later delivery
> [CEST Sep 19 19:12:11] error : Queued event file: unable to read event size -- end of file

> [...]
>
> At reload, everything is fine. Then one gets some errors during a reboot
> as Monit cannot connect to the mailserver at this time, which is normal
> since the mail server has been stopped before Monit. This is not a
> problem, as I will receive the mail after the reboot. The problem is
> the "Queued event file: unable to read event size -- end of file" errors
> every 2 minutes after the reboot, which fill my log file.

Can you check permissions on events dir & file? If possible, please check
new sid's version.

> the mail server has been stopped before Monit

This shouldn't be. Monit must be stopped first by init script (and
started last, by the way). That's - package default.

[Vincent Lefevre]

Control: found -1 1:5.20.0-4

Hi,

On 2017-01-09 15:02:11 +0300, Sergey Kirpichev wrote:
> On Wed, Oct 5, 2016 at 12:09 PM, Vincent Lefevre <vin...@vinc17.net> wrote:
> > [CEST Sep 19 19:10:11] info : Adding event to the queue file /var/lib/monit/events/1474305011_1bbbd00 for later delivery
> > [CEST Sep 19 19:12:11] error : Queued event file: unable to read event size -- end of file
> > [...]
> >
> > At reload, everything is fine. Then one gets some errors during a reboot
> > as Monit cannot connect to the mailserver at this time, which is normal
> > since the mail server has been stopped before Monit. This is not a
> > problem, as I will receive the mail after the reboot. The problem is
> > the "Queued event file: unable to read event size -- end of file" errors
> > every 2 minutes after the reboot, which fill my log file.
>
> Can you check permissions on events dir & file?

root@zira:/home/vinc17# ls -l /var/lib/monit
total 12
drwx------ 2 root root 4096 2017-01-06 18:16:28 events
-rw-r--r-- 1 root root 32 2015-07-07 13:17:34 id
-rw------- 1 root root 768 2017-01-09 13:21:03 state
root@zira:/home/vinc17# ls -l /var/lib/monit/events
total 0
-rw-r--r-- 1 root root 0 2015-07-25 17:15:17 1437837317_12a1a40
-rw-r--r-- 1 root root 0 2016-12-23 10:51:02 1482486662_5640726e2fa0

> If possible, please check new sid's version.

Same problem:

[...]
[CET Jan 9 13:17:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:17:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:19:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:19:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:21:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:21:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:23:03] error : Queued event file: unable to read event size -- end of file
[CET Jan 9 13:23:03] error : Queued event file: unable to read event size -- end of file

> > the mail server has been stopped before Monit
>
> This shouldn't be. Monit must be stopped first by init script (and
> started last, by the way). That's - package default.

Apparently not: there are lots of services stopped before monit.

--
Vincent Lefèvre <vin...@vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)

[Sergey B Kirpichev]

On Mon, Jan 09, 2017 at 01:32:59PM +0100, Vincent Lefevre wrote:
> > Can you check permissions on events dir & file?
>
> root@zira:/home/vinc17# ls -l /var/lib/monit
> total 12
> drwx------ 2 root root 4096 2017-01-06 18:16:28 events
> -rw-r--r-- 1 root root 32 2015-07-07 13:17:34 id
> -rw------- 1 root root 768 2017-01-09 13:21:03 state
> root@zira:/home/vinc17# ls -l /var/lib/monit/events
> total 0
> -rw-r--r-- 1 root root 0 2015-07-25 17:15:17 1437837317_12a1a40
> -rw-r--r-- 1 root root 0 2016-12-23 10:51:02 1482486662_5640726e2fa0
>
> > If possible, please check new sid's version.
>
> Same problem:

First file seems to be too old. Second - too (but not too much). What
if you clean up these files?

> > This shouldn't be. Monit must be stopped first by init script (and
> > started last, by the way). That's - package default.
>
> Apparently not: there are lots of services stopped before monit.

Are you using sysvinit and standard init-file for monit? It looks
like sysvinit-core - pruned on your system.

[Vincent Lefevre]

On 2017-01-09 15:54:40 +0300, Sergey B Kirpichev wrote:
> On Mon, Jan 09, 2017 at 01:32:59PM +0100, Vincent Lefevre wrote:
> > > Can you check permissions on events dir & file?
> >
> > root@zira:/home/vinc17# ls -l /var/lib/monit
> > total 12
> > drwx------ 2 root root 4096 2017-01-06 18:16:28 events
> > -rw-r--r-- 1 root root 32 2015-07-07 13:17:34 id
> > -rw------- 1 root root 768 2017-01-09 13:21:03 state
> > root@zira:/home/vinc17# ls -l /var/lib/monit/events
> > total 0
> > -rw-r--r-- 1 root root 0 2015-07-25 17:15:17 1437837317_12a1a40
> > -rw-r--r-- 1 root root 0 2016-12-23 10:51:02 1482486662_5640726e2fa0
> >
> > > If possible, please check new sid's version.
> >
> > Same problem:
>
> First file seems to be too old. Second - too (but not too much). What
> if you clean up these files?

The error messages no longer occur (without needing to restart monit).

If the problem was that some files were too old, then monit should
have done some clean up. BTW, shouldn't they be under /run?

> > > This shouldn't be. Monit must be stopped first by init script (and
> > > started last, by the way). That's - package default.
> >
> > Apparently not: there are lots of services stopped before monit.
>
> Are you using sysvinit and standard init-file for monit? It looks
> like sysvinit-core - pruned on your system.

I'm using systemd, as said in "System Information" in my bug report,
and I haven't changed the init files. But systemd provides LSB
compatibility.

[Sergey B Kirpichev]

On Mon, Jan 09, 2017 at 02:15:57PM +0100, Vincent Lefevre wrote:
> The error messages no longer occur (without needing to restart monit).

But with restart (monit or system) they DO appear again, correct?

> If the problem was that some files were too old, then monit should
> have done some clean up.

We can discuss solution when the reason for this problem will be identified.

> BTW, shouldn't they be under /run?

Maybe.

> I'm using systemd, as said in "System Information" in my bug report,
> and I haven't changed the init files. But systemd provides LSB
> compatibility.

Apparently, systemd support for LSB is bad in this case.

[Vincent Lefevre]

On 2017-01-09 16:53:52 +0300, Sergey B Kirpichev wrote:
> On Mon, Jan 09, 2017 at 02:15:57PM +0100, Vincent Lefevre wrote:
> > The error messages no longer occur (without needing to restart monit).
>
> But with restart (monit or system) they DO appear again, correct?

I've rebooted the machine, and the error message still no longer
appears. But the /var/lib/monit/events directory is empty.

(There are just the normal messages at start up due to systemd's
buggy LSB support.)

> > I'm using systemd, as said in "System Information" in my bug report,
> > and I haven't changed the init files. But systemd provides LSB
> > compatibility.
>
> Apparently, systemd support for LSB is bad in this case.

I've reported a bug:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=850703

[Sergey B Kirpichev]

On Mon, Jan 09, 2017 at 03:20:07PM +0100, Vincent Lefevre wrote:
> On 2017-01-09 16:53:52 +0300, Sergey B Kirpichev wrote:
> > On Mon, Jan 09, 2017 at 02:15:57PM +0100, Vincent Lefevre wrote:
> > > The error messages no longer occur (without needing to restart monit).
> >
> > But with restart (monit or system) they DO appear again, correct?
>
> I've rebooted the machine, and the error message still no longer
> appears. But the /var/lib/monit/events directory is empty.
>
> (There are just the normal messages at start up due to systemd's
> buggy LSB support.)

So, all mail-related problems - are present, event-files - were
created, but correctly removed?

If this is correct, problem seems to be solved in the new
version. If not - please try to reproduce situation, when
event-files are created.

BTW, I don't think, that monit should cleanup some "broken" (from his
current point of view) files in events dir.

[Vincent Lefevre]

On 2017-01-09 17:41:14 +0300, Sergey B Kirpichev wrote:
> On Mon, Jan 09, 2017 at 03:20:07PM +0100, Vincent Lefevre wrote:
> > On 2017-01-09 16:53:52 +0300, Sergey B Kirpichev wrote:
> > > On Mon, Jan 09, 2017 at 02:15:57PM +0100, Vincent Lefevre wrote:
> > > > The error messages no longer occur (without needing to restart monit).
> > >
> > > But with restart (monit or system) they DO appear again, correct?
> >
> > I've rebooted the machine, and the error message still no longer
> > appears. But the /var/lib/monit/events directory is empty.
> >
> > (There are just the normal messages at start up due to systemd's
> > buggy LSB support.)
>
> So, all mail-related problems - are present, event-files - were
> created, but correctly removed?

Yes, it seems so... unless the problem is not always reproducible
(e.g. if there's some race condition).

I also wonder whether suspending the laptop can also yield the
issue.

> If this is correct, problem seems to be solved in the new
> version. If not - please try to reproduce situation, when
> event-files are created.

I'll try to reproduce the problem by rebooting the machine
(not before Wednesday, though).

> BTW, I don't think, that monit should cleanup some "broken" (from
> his current point of view) files in events dir.

Any reason?

Note: The files were empty, so that they didn't contain any meaningful
information, I suppose.

[Sergey B Kirpichev]

On Mon, Jan 09, 2017 at 04:09:47PM +0100, Vincent Lefevre wrote:
> Yes, it seems so... unless the problem is not always reproducible
> (e.g. if there's some race condition).
>
> I also wonder whether suspending the laptop can also yield the
> issue.
>
> > If this is correct, problem seems to be solved in the new
> > version. If not - please try to reproduce situation, when
> > event-files are created.
>
> I'll try to reproduce the problem by rebooting the machine
> (not before Wednesday, though).

Ok, I'll wait if you can reproduce the problem. Unfortunately, I can't.

> > BTW, I don't think, that monit should cleanup some "broken" (from
> > his current point of view) files in events dir.
>
> Any reason?
>
> Note: The files were empty, so that they didn't contain any meaningful
> information, I suppose.

File also has metadata. They may be essential
for debugging, as an example.

The creation of an empty file - seems to be the problem. Monit shoundn't
just hide problems.

[Sergey B Kirpichev]

tags 839804 -moreinfo +unreproducible
thanks

On Mon, Jan 09, 2017 at 04:09:47PM +0100, Vincent Lefevre wrote:

> Yes, it seems so... unless the problem is not always reproducible
> (e.g. if there's some race condition).
>
> I also wonder whether suspending the laptop can also yield the
> issue.
>
> > If this is correct, problem seems to be solved in the new
> > version. If not - please try to reproduce situation, when
> > event-files are created.
>
> I'll try to reproduce the problem by rebooting the machine
> (not before Wednesday, though).

I'll wait for your reply till the end of week. Then, I'll
close bug as unreproducible, if nothing happens.