nagios-nrpe-server-4 is creating incorrect log spam

Bug #1888184 reported by JP Vossen
28
This bug affects 5 people
Affects Status Importance Assigned to Milestone
nagios-nrpe (Ubuntu)
Undecided
Unassigned

Bug Description

Server: Debian 10 (buster), nagios-nrpe-plugin-3.2.1-2
Node: Linux Mint 20 (Ulyana), using Ubuntu Focal, nagios-nrpe-server-4.0.0-2ubuntu1

Icinga1 server on Debian monitoring a bunch of LinuxMint-19.3, using protocol v3, and working just fine since last year. I just built 2x new install Mint-20.0 nodes and on *both* of them, for every single `check_nrpe` from the server to the node, the node spams its logs with:
* Jul 19 22:02:56 node nrpe[13152]: Error: (use_ssl == true): Request packet version was invalid!
* Jul 19 22:02:56 node nrpe[13152]: Could not read request from client 192.168.1.11, bailing out...
* Jul 19 22:02:56 node nrpe[13152]: INFO: SSL Socket Shutdown.

And the server spams its logs with:
* Jul 19 22:02:05 server check_nrpe: Remote 192.168.1.120 does not support Version 3 Packets

Yet despite all of that noise, the checks actually work just fine.

Expected: the checks using nrpe-v3 should Just Work with no incorrect log spam
What happens: the nrpe-v3 checks work but spam the logs on both sides

Nice-to-have: any clues on how to cut down the log spam until the fix is released.
Using `/etc/nagios/nrpe.d/node.cfg` to set `debug=1` or `debug=0` works to turn debugs logs on and off, but that has no effect on the rest of the spam.

Server side sanity checks:
```
$ /usr/lib/nagios/plugins/check_nrpe -H node-mint20.0 -n
CHECK_NRPE: Receive header underflow - only -1 bytes received (4 expected).

$ /usr/lib/nagios/plugins/check_nrpe -H node-mint20.0 -2 # (NO LOG SPAM)
NRPE v4.0.0

$ /usr/lib/nagios/plugins/check_nrpe -H node-mint20.0 # (v3 STILL WORKS, but with log spam)
NRPE v4.0.0

$ /usr/lib/nagios/plugins/check_nrpe -H node-mint19.3
NRPE v3.2.1
```

SERVER side test run, with deliberate errors to bracket the logs:
```
[root@drake:T1:L1:C4975:J0:2020-07-20_01:02:04_EDT]
/root# /usr/lib/nagios/plugins/check_nrpe -H node -c check_load_start
NRPE: Command 'check_load_start' not defined

[root@drake:T1:L1:C4976:J0:2020-07-20_01:02:07_EDT]
/root# /usr/lib/nagios/plugins/check_nrpe -H node -c check_load
OK - load average: 0.33, 0.14, 0.05|load1=0.330;3.000;5.000;0; load5=0.140;2.000;4.000;0; load15=0.050;2.000;4.000;0;

[root@drake:T1:L1:C4976:J0:2020-07-20_01:02:12_EDT]
/root# /usr/lib/nagios/plugins/check_nrpe -H node -c check_end
NRPE: Command 'check_end' not defined
```

NODE side debug log, notes the errors, note the LOG SPAM, note the check still runs:
```
Jul 20 01:01:52 node systemd[1]: nagios-nrpe-server.service: Succeeded.
Jul 20 01:01:52 node nrpe[18424]: Added command[check_ntp_peer]=/usr/lib/nagios/plugins/check_ntp_peer -H localhost
Jul 20 01:01:52 node nrpe[18424]: Added command[check_total_procs]=/usr/lib/nagios/plugins/check_procs -w 325 -c 360
Jul 20 01:01:52 node nrpe[18424]: Added command[check_disks]=/usr/lib/nagios/plugins/check_disk -w 15% -c 8% -l -X tmpfs -X udev -X usbfs -X fuse -X fuse.sshfs -X fuse.gvfsd-fuse -X fuse.gvfs-fuse-daemon -X squashfs -x /run/docker/netns/default
Jul 20 01:01:52 node nrpe[18424]: Added command[check_load]=/usr/lib/nagios/plugins/check_load -w 3,2,2 -c 5,4,4
Jul 20 01:01:52 node nrpe[18424]: INFO: SSL/TLS initialized. All network traffic will be encrypted.
Jul 20 01:01:52 node nrpe[18424]: Starting up daemon
Jul 20 01:01:52 node nrpe[18424]: SETUP_WAIT_CONN FOR: IPv4 address: 0.0.0.0 ((null))
Jul 20 01:01:52 node nrpe[18424]: Server listening on 0.0.0.0 port 5666.
Jul 20 01:01:52 node nrpe[18424]: SETUP_WAIT_CONN FOR: IPv4 address: :: ((null))
Jul 20 01:01:52 node nrpe[18424]: Server listening on :: port 5666.
Jul 20 01:01:52 node nrpe[18424]: Listening for connections on port 5666
Jul 20 01:01:52 node nrpe[18424]: Allowing connections from: 127.0.0.1,192.168.1.11
Jul 20 01:02:07 node nrpe[19664]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 12975
Jul 20 01:02:07 node nrpe[19664]: Connection from 192.168.1.11 port 12975
Jul 20 01:02:07 node nrpe[19664]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:07 node nrpe[19664]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:07 node nrpe[19664]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:07 node nrpe[19664]: Host address is in allowed_hosts
Jul 20 01:02:07 node nrpe[19664]: Error: (use_ssl == true): Request packet version was invalid!
Jul 20 01:02:07 node nrpe[19664]: Could not read request from client 192.168.1.11, bailing out...
Jul 20 01:02:07 node nrpe[19664]: INFO: SSL Socket Shutdown.
Jul 20 01:02:07 node nrpe[19664]: Connection from 192.168.1.11 closed.
Jul 20 01:02:07 node nrpe[19671]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 13487
Jul 20 01:02:07 node nrpe[19671]: Connection from 192.168.1.11 port 13487
Jul 20 01:02:07 node nrpe[19671]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:07 node nrpe[19671]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:07 node nrpe[19671]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:07 node nrpe[19671]: Host address is in allowed_hosts
Jul 20 01:02:07 node nrpe[19671]: Host 192.168.1.11 is asking for command 'check_load_start' to be run...
Jul 20 01:02:07 node nrpe[19671]: NRPE: Command 'check_load_start' not defined
Jul 20 01:02:07 node nrpe[19671]: Return Code: 3, Output: NRPE: Command 'check_load_start' not defined
Jul 20 01:02:07 node nrpe[19671]: Connection from 192.168.1.11 closed.
Jul 20 01:02:11 node nrpe[19673]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 14511
Jul 20 01:02:11 node nrpe[19673]: Connection from 192.168.1.11 port 14511
Jul 20 01:02:11 node nrpe[19673]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:11 node nrpe[19673]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:11 node nrpe[19673]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:11 node nrpe[19673]: Host address is in allowed_hosts
Jul 20 01:02:12 node nrpe[19673]: Error: (use_ssl == true): Request packet version was invalid!
Jul 20 01:02:12 node nrpe[19673]: Could not read request from client 192.168.1.11, bailing out...
Jul 20 01:02:12 node nrpe[19673]: INFO: SSL Socket Shutdown.
Jul 20 01:02:12 node nrpe[19673]: Connection from 192.168.1.11 closed.
Jul 20 01:02:12 node nrpe[19675]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 15023
Jul 20 01:02:12 node nrpe[19675]: Connection from 192.168.1.11 port 15023
Jul 20 01:02:12 node nrpe[19675]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:12 node nrpe[19675]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:12 node nrpe[19675]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:12 node nrpe[19675]: Host address is in allowed_hosts
Jul 20 01:02:12 node nrpe[19675]: Host 192.168.1.11 is asking for command 'check_load' to be run...
Jul 20 01:02:12 node nrpe[19675]: Running command: /usr/lib/nagios/plugins/check_load -w 3,2,2 -c 5,4,4
Jul 20 01:02:12 node nrpe[19676]: WARNING: my_system() seteuid(0): Operation not permitted
Jul 20 01:02:12 node nrpe[19675]: Command completed with return code 0 and output: OK - load average: 0.33, 0.14, 0.05|load1=0.330;3.000;5.000;0; load5=0.140;2.000;4.000;0; load15=0.050;2.000;4.000;0;
Jul 20 01:02:12 node nrpe[19675]: Return Code: 0, Output: OK - load average: 0.33, 0.14, 0.05|load1=0.330;3.000;5.000;0; load5=0.140;2.000;4.000;0; load15=0.050;2.000;4.000;0;
Jul 20 01:02:12 node nrpe[19675]: Connection from 192.168.1.11 closed.
Jul 20 01:02:15 node nrpe[19684]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 16047
Jul 20 01:02:15 node nrpe[19684]: Connection from 192.168.1.11 port 16047
Jul 20 01:02:15 node nrpe[19684]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:15 node nrpe[19684]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:15 node nrpe[19684]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:15 node nrpe[19684]: Host address is in allowed_hosts
Jul 20 01:02:15 node nrpe[19684]: Error: (use_ssl == true): Request packet version was invalid!
Jul 20 01:02:15 node nrpe[19684]: Could not read request from client 192.168.1.11, bailing out...
Jul 20 01:02:15 node nrpe[19684]: INFO: SSL Socket Shutdown.
Jul 20 01:02:15 node nrpe[19684]: Connection from 192.168.1.11 closed.
Jul 20 01:02:15 node nrpe[19686]: CONN_CHECK_PEER: checking if host is allowed: 192.168.1.11 port 16559
Jul 20 01:02:15 node nrpe[19686]: Connection from 192.168.1.11 port 16559
Jul 20 01:02:15 node nrpe[19686]: is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<
Jul 20 01:02:15 node nrpe[19686]: message repeated 2 times: [ is_an_allowed_host (AF_INET): is host >192.168.1.11< an allowed host >192.168.1.11<]
Jul 20 01:02:15 node nrpe[19686]: is_an_allowed_host (AF_INET): host is in allowed host list!
Jul 20 01:02:15 node nrpe[19686]: Host address is in allowed_hosts
Jul 20 01:02:15 node nrpe[19686]: Host 192.168.1.11 is asking for command 'check_end' to be run...
Jul 20 01:02:15 node nrpe[19686]: NRPE: Command 'check_end' not defined
Jul 20 01:02:15 node nrpe[19686]: Return Code: 3, Output: NRPE: Command 'check_end' not defined
Jul 20 01:02:15 node nrpe[19686]: Connection from 192.168.1.11 closed.
```

Revision history for this message
Lucas Kanashiro (lucaskanashiro) wrote :

Thanks for taking the time to report this bug and trying to make Ubuntu better.

I've seen some people facing issues regarding the packet version compatibility, you have version 3 and 4 in your setup. I tried to make a quick research about any compatibility issue between version 3 and 4 but I did not find something useful. I found a recent post on the nagios support forum but I do not have permission to access it, from its short description I got that "agents are falling back to packet version 2 when query an agent in version 4 by a plugin in version 3". This seems to match your case and it might be an upstream issue. It'd be great if you could engage in a discussion about it with upstream. In case you do that please link it here.

Since you described it is still working, you can try to follow one of the solutions described in this article to silence those errors for now:

https://support.nagios.com/kb/article/nrpe-remote-does-not-support-version-3-packets-786.html

Changed in nagios-nrpe (Ubuntu):
status: New → Triaged
Revision history for this message
JP Vossen (jp-jpsdomain) wrote :

Thanks for the clues! I think I'd seen that URL in my research but the `rsyslog` filter had escaped me. I'll see about pestering upstream when time permits, any hints on where or who to pester appreciated.

For the record, for Mint-20 or Ubuntu Focal using stock `rsyslog` this prevented the log spam but isn't a real fix:
```
sudo vi /etc/rsyslog.d/10-nrpe-log-spam.conf
sudo systemctl restart rsyslog
```

File contents to "fix" NODE spam:
```
# /etc/rsyslog.d/10-nrpe-log-spam.conf
# 2020-07-26 Sun: Suppress useless NRPE log spam
# See https://bugs.launchpad.net/ubuntu/+source/nagios-nrpe/+bug/1888184
:msg, contains, "Request packet version was invalid" stop
:msg, contains, "Could not read request from client 192.168.1.11, bailing out" stop
:msg, contains, "INFO: SSL Socket Shutdown" stop
```

File contents to "fix" Server spam:
```
# /etc/rsyslog.d/10-nrpe-log-spam.conf
# 2020-07-26 Sun: Suppress useless NRPE log spam
# See https://bugs.launchpad.net/ubuntu/+source/nagios-nrpe/+bug/1888184
:msg, contains, "does not support Version 3 Packets" stop
```

Revision history for this message
Ken Marsh (kmarsh) wrote :

This is a Focal v4 check_nrpe querying bionic NRPE v3 and should work without spamming logs. I am seeing in syslog:

check_nrpe - - - Remote 10.1.2.3 does not support version 3/4 packets

However checks are working.

Revision history for this message
Christian Clifford (cmakaloclifford) wrote :

We have similar issue but with the same version on both sides.

The checks actually works (it seems), but generates a lot of these errors shown below.

### On a server being checked ###

# Installed packages:
nagios-nrpe-server/focal,focal,now 4.0.0-2ubuntu1 amd64 [installed]

# Output from syslog:
2021-09-30 15:50:22 INFO: SSL Socket Shutdown.
2021-09-30 15:50:22 Could not read request from client *IP*, bailing out...
2021-09-30 15:50:22 Error: (use_ssl == true): Request packet version was invalid!

### On the monitor server ###

# Installed packages:
nagios-nrpe-plugin/focal,now 4.0.0-2ubuntu1 amd64 [installed]
nagios-nrpe-server/focal,now 4.0.0-2ubuntu1 amd64 [installed]

# Output from syslog:
2021-09-30 15:50:22 Remote *IP* does not support version 3/4 packets

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers