[libvirt] [PATCH 0/3] log|lock daemon: Don't spam logs with IO error messages after client disconnects

See patch 3 for explanation Peter Krempa (3): rpc: socket: Add possibility to suppress errors on read hangup rpc: serverclient: Add option to suppress errors on EOF (log|lock)daemon: Don't spam logs with IO error messages after client disconnects src/locking/lock_daemon.c | 3 +++ src/logging/log_daemon.c | 3 +++ src/rpc/virnetserverclient.c | 13 +++++++++++++ src/rpc/virnetserverclient.h | 2 ++ src/rpc/virnetsocket.c | 33 +++++++++++++++++++++++++++------ src/rpc/virnetsocket.h | 2 ++ 6 files changed, 50 insertions(+), 6 deletions(-) -- 2.12.0

In some cases a read error due to connection hangup is expected. This patch adds a flag that removes the logging of a virError in such case. --- src/rpc/virnetsocket.c | 33 +++++++++++++++++++++++++++------ src/rpc/virnetsocket.h | 2 ++ 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/src/rpc/virnetsocket.c b/src/rpc/virnetsocket.c index 325a7c7cf..4d1dc6446 100644 --- a/src/rpc/virnetsocket.c +++ b/src/rpc/virnetsocket.c @@ -82,6 +82,7 @@ struct _virNetSocket { int errfd; bool client; bool ownsFd; + bool quietEOF; /* Event callback fields */ virNetSocketIOFunc func; @@ -1792,12 +1793,18 @@ static ssize_t virNetSocketReadWire(virNetSocketPtr sock, char *buf, size_t len) _("Cannot recv data")); ret = -1; } else if (ret == 0) { - if (errout) - virReportSystemError(EIO, - _("End of file while reading data: %s"), errout); - else - virReportSystemError(EIO, "%s", - _("End of file while reading data")); + if (sock->quietEOF) { + VIR_DEBUG("socket='%p' EOF while reading: errout='%s'", + socket, NULLSTR(errout)); + } else { + if (errout) + virReportSystemError(EIO, + _("End of file while reading data: %s"), + errout); + else + virReportSystemError(EIO, "%s", + _("End of file while reading data")); + } ret = -1; } @@ -2233,3 +2240,17 @@ void virNetSocketClose(virNetSocketPtr sock) virObjectUnlock(sock); } + + +/** + * virNetSocketSetQuietEOF: + * @sock: socket object pointer + * + * Disables reporting I/O errors as a virError when @socket is closed while + * reading data. + */ +void +virNetSocketSetQuietEOF(virNetSocketPtr sock) +{ + sock->quietEOF = true; +} diff --git a/src/rpc/virnetsocket.h b/src/rpc/virnetsocket.h index 56c75c030..1e75ee62b 100644 --- a/src/rpc/virnetsocket.h +++ b/src/rpc/virnetsocket.h @@ -143,6 +143,8 @@ int virNetSocketGetSELinuxContext(virNetSocketPtr sock, int virNetSocketSetBlocking(virNetSocketPtr sock, bool blocking); +void virNetSocketSetQuietEOF(virNetSocketPtr sock); + ssize_t virNetSocketRead(virNetSocketPtr sock, char *buf, size_t len); ssize_t virNetSocketWrite(virNetSocketPtr sock, const char *buf, size_t len); -- 2.12.0

On Fri, Mar 17, 2017 at 04:48:49PM +0100, Peter Krempa wrote:
In some cases a read error due to connection hangup is expected. This patch adds a flag that removes the logging of a virError in such case. --- src/rpc/virnetsocket.c | 33 +++++++++++++++++++++++++++------ src/rpc/virnetsocket.h | 2 ++ 2 files changed, 29 insertions(+), 6 deletions(-)
diff --git a/src/rpc/virnetsocket.c b/src/rpc/virnetsocket.c index 325a7c7cf..4d1dc6446 100644 --- a/src/rpc/virnetsocket.c +++ b/src/rpc/virnetsocket.c @@ -82,6 +82,7 @@ struct _virNetSocket { int errfd; bool client; bool ownsFd; + bool quietEOF;
/* Event callback fields */ virNetSocketIOFunc func; @@ -1792,12 +1793,18 @@ static ssize_t virNetSocketReadWire(virNetSocketPtr sock, char *buf, size_t len) _("Cannot recv data")); ret = -1; } else if (ret == 0) { - if (errout) - virReportSystemError(EIO, - _("End of file while reading data: %s"), errout); - else - virReportSystemError(EIO, "%s", - _("End of file while reading data")); + if (sock->quietEOF) { + VIR_DEBUG("socket='%p' EOF while reading: errout='%s'", + socket, NULLSTR(errout)); + } else { + if (errout) + virReportSystemError(EIO, + _("End of file while reading data: %s"), + errout); + else + virReportSystemError(EIO, "%s", + _("End of file while reading data")); + } ret = -1;
I'm a little uncomfortable with the idea of returning '-1' without reporting an error message. I would suggest returning 0, but we used that to indicate EAGAIN condition. Can we at least make it return '-2' as a distinct code when we don't report errors. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|

On Fri, Mar 17, 2017 at 16:10:35 +0000, Daniel Berrange wrote:
On Fri, Mar 17, 2017 at 04:48:49PM +0100, Peter Krempa wrote:
In some cases a read error due to connection hangup is expected. This patch adds a flag that removes the logging of a virError in such case. --- src/rpc/virnetsocket.c | 33 +++++++++++++++++++++++++++------ src/rpc/virnetsocket.h | 2 ++ 2 files changed, 29 insertions(+), 6 deletions(-)
[...]
+ } else { + if (errout) + virReportSystemError(EIO, + _("End of file while reading data: %s"), + errout); + else + virReportSystemError(EIO, "%s", + _("End of file while reading data")); + } ret = -1;
I'm a little uncomfortable with the idea of returning '-1' without reporting an error message. I would suggest returning 0, but we used that to indicate EAGAIN condition. Can we at least make it return '-2' as a distinct code when we don't report errors.
That is fine by me. The callers that will ignore the error don't really care why the read failed currently.

The protocol may not use an explicit API to close the connection and just close the socket instead. Add option to suppress errors in such case. --- src/rpc/virnetserverclient.c | 13 +++++++++++++ src/rpc/virnetserverclient.h | 2 ++ 2 files changed, 15 insertions(+) diff --git a/src/rpc/virnetserverclient.c b/src/rpc/virnetserverclient.c index 81da82cab..85857bc3e 100644 --- a/src/rpc/virnetserverclient.c +++ b/src/rpc/virnetserverclient.c @@ -1637,3 +1637,16 @@ virNetServerClientGetInfo(virNetServerClientPtr client, virObjectUnlock(client); return ret; } + + +/** + * virNetServerClientSetQuietEOF: + * + * Don't report errors for protocols that close connection by hangup of the + * socket rather than calling an API to close it. + */ +void +virNetServerClientSetQuietEOF(virNetServerClientPtr client) +{ + virNetSocketSetQuietEOF(client->sock); +} diff --git a/src/rpc/virnetserverclient.h b/src/rpc/virnetserverclient.h index a53cc00b2..e45c78882 100644 --- a/src/rpc/virnetserverclient.h +++ b/src/rpc/virnetserverclient.h @@ -152,4 +152,6 @@ int virNetServerClientGetInfo(virNetServerClientPtr client, bool *readonly, char **sock_addr, virIdentityPtr *identity); +void virNetServerClientSetQuietEOF(virNetServerClientPtr client); + #endif /* __VIR_NET_SERVER_CLIENT_H__ */ -- 2.12.0

The log and lock protocol don't have an extra handshake to close the connection. Instead they just close the socket. Unfortunately that resulted into a lot of spurious garbage logged to the system log files: 2017-03-17 14:00:09.730+0000: 4714: error : virNetSocketReadWire:1800 : End of file while reading data: Input/output error or in the journal as: Mar 13 16:19:33 xxxx virtlogd[32360]: End of file while reading data: Input/output error Use the new facility in the netserverclient to suppress the IO error report from the virNetSocket layer. --- src/locking/lock_daemon.c | 3 +++ src/logging/log_daemon.c | 3 +++ 2 files changed, 6 insertions(+) diff --git a/src/locking/lock_daemon.c b/src/locking/lock_daemon.c index 1c94ddd05..12485e966 100644 --- a/src/locking/lock_daemon.c +++ b/src/locking/lock_daemon.c @@ -712,6 +712,9 @@ virLockDaemonClientNew(virNetServerClientPtr client, } } + /* there's no closing handshake in the locking protocol */ + virNetServerClientSetQuietEOF(client); + return priv; error: diff --git a/src/logging/log_daemon.c b/src/logging/log_daemon.c index 5997cce9d..d878efa63 100644 --- a/src/logging/log_daemon.c +++ b/src/logging/log_daemon.c @@ -572,6 +572,9 @@ virLogDaemonClientNew(virNetServerClientPtr client, } } + /* there's no closing handshake in the logging protocol */ + virNetServerClientSetQuietEOF(client); + return priv; error: -- 2.12.0

On Fri, Mar 17, 2017 at 04:48:51PM +0100, Peter Krempa wrote:
The log and lock protocol don't have an extra handshake to close the connection. Instead they just close the socket. Unfortunately that resulted into a lot of spurious garbage logged to the system log files:
2017-03-17 14:00:09.730+0000: 4714: error : virNetSocketReadWire:1800 : End of file while reading data: Input/output error
or in the journal as:
Mar 13 16:19:33 xxxx virtlogd[32360]: End of file while reading data: Input/output error
Use the new facility in the netserverclient to suppress the IO error report from the virNetSocket layer. --- src/locking/lock_daemon.c | 3 +++ src/logging/log_daemon.c | 3 +++ 2 files changed, 6 insertions(+)
diff --git a/src/locking/lock_daemon.c b/src/locking/lock_daemon.c index 1c94ddd05..12485e966 100644 --- a/src/locking/lock_daemon.c +++ b/src/locking/lock_daemon.c @@ -712,6 +712,9 @@ virLockDaemonClientNew(virNetServerClientPtr client, } }
+ /* there's no closing handshake in the locking protocol */ + virNetServerClientSetQuietEOF(client); + return priv;
error: diff --git a/src/logging/log_daemon.c b/src/logging/log_daemon.c index 5997cce9d..d878efa63 100644 --- a/src/logging/log_daemon.c +++ b/src/logging/log_daemon.c @@ -572,6 +572,9 @@ virLogDaemonClientNew(virNetServerClientPtr client, } }
+ /* there's no closing handshake in the logging protocol */ + virNetServerClientSetQuietEOF(client); + return priv;
Ok, so you're setting this flag server side, and the virNetSocketRead is triggered by virNetServerClientRead, in turn by n event handler virNetServerClientDispatchRead. This method doesn't care about the error message reported by virNetSocketRead at all - it simply marks the client as needing closing. So yeah, returning without setting an error is reasonable, though I'd still prefer to have it return -2 rather than -1 for the case where no error is reported. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|

On Fri, Mar 17, 2017 at 04:48:48PM +0100, Peter Krempa wrote:
See patch 3 for explanation
Peter Krempa (3): rpc: socket: Add possibility to suppress errors on read hangup rpc: serverclient: Add option to suppress errors on EOF (log|lock)daemon: Don't spam logs with IO error messages after client disconnects
ACK, if you add 'ret = -2' in the first patch where mentioned Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|

On Fri, Mar 17, 2017 at 16:15:03 +0000, Daniel Berrange wrote:
On Fri, Mar 17, 2017 at 04:48:48PM +0100, Peter Krempa wrote:
See patch 3 for explanation
Peter Krempa (3): rpc: socket: Add possibility to suppress errors on read hangup rpc: serverclient: Add option to suppress errors on EOF (log|lock)daemon: Don't spam logs with IO error messages after client disconnects
ACK, if you add 'ret = -2' in the first patch where mentioned
Thanks, I've tweaked it and pushed. Peter
participants (2)
-
Daniel P. Berrange
-
Peter Krempa