[PATCH] char: fix logging when chardev write fails

[PATCH] char: fix logging when chardev write fails

[Daniel P. Berrangé]

The qemu_chr_write_buffer() method sends data to the chardev backend for
writing, and then also writes to the log file. In case the chardev
backend only writes part of the data buffer, we need to make sure we
only log the same subset. qemu_chr_write_buffer() will be invoked again
later to write the rest of the buffer.

In the case the chardev backend returns an error though, no further
attempts to likely to be made to write the data. We must therefore write
the entire buffer to the log immediately.

An example where this is important is with the socket backend. This will
return -1 for all writes if no client is currently connected. We still
wish to write data to the log file when no client is present though.
This used to work because the chardev would return "len" to pretend it
had written all data when no client is connected, but this changed to
return an error in

  commit 271094474b65de1ad7aaf729938de3d9b9d0d36f
  Author: Dima Stepanov <dimastep@yandex-team.ru>
  Date: Thu May 28 12:11:18 2020 +0300

    char-socket: return -1 in case of disconnect during tcp_chr_write

and this broke the logging, resulting in all data being discarded when
no client is present.

Fixes: https://bugs.launchpad.net/qemu/+bug/1893691
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 chardev/char.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/chardev/char.c b/chardev/char.c
index 77e7ec814f..e30cd025f5 100644
--- a/chardev/char.c
+++ b/chardev/char.c
@@ -138,7 +138,20 @@ static int qemu_chr_write_buffer(Chardev *s,
         }
     }
     if (*offset > 0) {
+        /*
+         * If some data was written by backend, we should
+         * only log what was actually written. This method
+         * may be invoked again to write the remaining
+         * method, thus we'll log the remainder at that time.
+         */
         qemu_chr_write_log(s, buf, *offset);
+    } else if (res < 0) {
+        /*
+         * If a fatal error was reported by the backend,
+         * assume this method won't be invoked again with
+         * this buffer, so log it all right away.
+         */
+        qemu_chr_write_log(s, buf, len);
     }
     qemu_mutex_unlock(&s->chr_write_lock);
 
-- 
2.26.2

Re: [PATCH] char: fix logging when chardev write fails

[Marc-André Lureau]

On Mon, Sep 14, 2020 at 2:31 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
>
> The qemu_chr_write_buffer() method sends data to the chardev backend for
> writing, and then also writes to the log file. In case the chardev
> backend only writes part of the data buffer, we need to make sure we
> only log the same subset. qemu_chr_write_buffer() will be invoked again
> later to write the rest of the buffer.
>
> In the case the chardev backend returns an error though, no further
> attempts to likely to be made to write the data. We must therefore write
> the entire buffer to the log immediately.
>
> An example where this is important is with the socket backend. This will
> return -1 for all writes if no client is currently connected. We still
> wish to write data to the log file when no client is present though.
> This used to work because the chardev would return "len" to pretend it
> had written all data when no client is connected, but this changed to
> return an error in
>
>   commit 271094474b65de1ad7aaf729938de3d9b9d0d36f
>   Author: Dima Stepanov <dimastep@yandex-team.ru>
>   Date: Thu May 28 12:11:18 2020 +0300
>
>     char-socket: return -1 in case of disconnect during tcp_chr_write
>
> and this broke the logging, resulting in all data being discarded when
> no client is present.
>
> Fixes: https://bugs.launchpad.net/qemu/+bug/1893691
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>

> ---
>  chardev/char.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
>
> diff --git a/chardev/char.c b/chardev/char.c
> index 77e7ec814f..e30cd025f5 100644
> --- a/chardev/char.c
> +++ b/chardev/char.c
> @@ -138,7 +138,20 @@ static int qemu_chr_write_buffer(Chardev *s,
>          }
>      }
>      if (*offset > 0) {
> +        /*
> +         * If some data was written by backend, we should
> +         * only log what was actually written. This method
> +         * may be invoked again to write the remaining
> +         * method, thus we'll log the remainder at that time.
> +         */
>          qemu_chr_write_log(s, buf, *offset);
> +    } else if (res < 0) {
> +        /*
> +         * If a fatal error was reported by the backend,
> +         * assume this method won't be invoked again with
> +         * this buffer, so log it all right away.
> +         */
> +        qemu_chr_write_log(s, buf, len);
>      }
>      qemu_mutex_unlock(&s->chr_write_lock);
>
> --
> 2.26.2
>

Re: [PATCH] char: fix logging when chardev write fails

[Paolo Bonzini]

On 14/09/20 12:31, Daniel P. Berrangé wrote:
> The qemu_chr_write_buffer() method sends data to the chardev backend for
> writing, and then also writes to the log file. In case the chardev
> backend only writes part of the data buffer, we need to make sure we
> only log the same subset. qemu_chr_write_buffer() will be invoked again
> later to write the rest of the buffer.
> 
> In the case the chardev backend returns an error though, no further
> attempts to likely to be made to write the data. We must therefore write
> the entire buffer to the log immediately.
> 
> An example where this is important is with the socket backend. This will
> return -1 for all writes if no client is currently connected. We still
> wish to write data to the log file when no client is present though.
> This used to work because the chardev would return "len" to pretend it
> had written all data when no client is connected, but this changed to
> return an error in
> 
>   commit 271094474b65de1ad7aaf729938de3d9b9d0d36f
>   Author: Dima Stepanov <dimastep@yandex-team.ru>
>   Date: Thu May 28 12:11:18 2020 +0300
> 
>     char-socket: return -1 in case of disconnect during tcp_chr_write
> 
> and this broke the logging, resulting in all data being discarded when
> no client is present.
> 
> Fixes: https://bugs.launchpad.net/qemu/+bug/1893691
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  chardev/char.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/chardev/char.c b/chardev/char.c
> index 77e7ec814f..e30cd025f5 100644
> --- a/chardev/char.c
> +++ b/chardev/char.c
> @@ -138,7 +138,20 @@ static int qemu_chr_write_buffer(Chardev *s,
>          }
>      }
>      if (*offset > 0) {
> +        /*
> +         * If some data was written by backend, we should
> +         * only log what was actually written. This method
> +         * may be invoked again to write the remaining
> +         * method, thus we'll log the remainder at that time.
> +         */
>          qemu_chr_write_log(s, buf, *offset);
> +    } else if (res < 0) {
> +        /*
> +         * If a fatal error was reported by the backend,
> +         * assume this method won't be invoked again with
> +         * this buffer, so log it all right away.
> +         */
> +        qemu_chr_write_log(s, buf, len);
>      }
>      qemu_mutex_unlock(&s->chr_write_lock);
>  
> 

Queued, thanks.

Paolo