[1/1] log: fix hanged connect from virt-manager to libvirt
diff mbox

Message ID 1457012886-7626-1-git-send-email-den@openvz.org
State New
Headers show

Commit Message

Denis V. Lunev March 3, 2016, 1:48 p.m. UTC
libvirt in this case spawns
  /usr/bin/qemu-system-x86_64 -S -no-user-config -nodefaults -nographic
    -M none
    -qmp unix:/var/lib/libvirt/qemu/capabilities.monitor.sock,server,nowait
    -pidfile /var/lib/libvirt/qemu/capabilities.pidfile -daemonize
and with CONFIG_TRACE_LOG this process hangs as stderr becomes redirected
to terminal (qemu_logfile == stderr). We do not have redirection to
/dev/null in this case which is necessary.

Broken by:
    commit 96c33a4523ee1abe382ce4ff3e82b90ba78aa186
    Author: Dimitris Aragiorgis <dimara@arrikto.com>
    Date:   Thu Feb 18 13:38:38 2016 +0200

    log: Redirect stderr to logfile if deamonized

We should also take into account log filename change in runtime through
QMP/HMP, when the log could be even closed. In this case stderr should
be tweaked accordingly.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Dimitris Aragiorgis <dimara@arrikto.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 include/qemu/log.h | 4 ++++
 os-posix.c         | 2 +-
 util/log.c         | 7 ++-----
 3 files changed, 7 insertions(+), 6 deletions(-)

Comments

Paolo Bonzini March 3, 2016, 1:49 p.m. UTC | #1
On 03/03/2016 14:48, Denis V. Lunev wrote:
> libvirt in this case spawns
>   /usr/bin/qemu-system-x86_64 -S -no-user-config -nodefaults -nographic
>     -M none
>     -qmp unix:/var/lib/libvirt/qemu/capabilities.monitor.sock,server,nowait
>     -pidfile /var/lib/libvirt/qemu/capabilities.pidfile -daemonize
> and with CONFIG_TRACE_LOG this process hangs as stderr becomes redirected
> to terminal (qemu_logfile == stderr). We do not have redirection to
> /dev/null in this case which is necessary.
> 
> Broken by:
>     commit 96c33a4523ee1abe382ce4ff3e82b90ba78aa186
>     Author: Dimitris Aragiorgis <dimara@arrikto.com>
>     Date:   Thu Feb 18 13:38:38 2016 +0200
> 
>     log: Redirect stderr to logfile if deamonized
> 
> We should also take into account log filename change in runtime through
> QMP/HMP, when the log could be even closed. In this case stderr should
> be tweaked accordingly.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Dimitris Aragiorgis <dimara@arrikto.com>
> CC: Paolo Bonzini <pbonzini@redhat.com>
> CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

A patch has been posted already, and I'll send a pull request tomorrow.

Paolo

> ---
>  include/qemu/log.h | 4 ++++
>  os-posix.c         | 2 +-
>  util/log.c         | 7 ++-----
>  3 files changed, 7 insertions(+), 6 deletions(-)
> 
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index dda65fd..8083f82 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -92,6 +92,10 @@ static inline void qemu_log_close(void)
>          }
>          qemu_logfile = NULL;
>      }
> +
> +    if (is_daemonized()) {
> +        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
> +    }
>  }
>  
>  /* define log items */
> diff --git a/os-posix.c b/os-posix.c
> index 92fa3ba..d4b2a91 100644
> --- a/os-posix.c
> +++ b/os-posix.c
> @@ -277,7 +277,7 @@ void os_setup_post(void)
>          dup2(fd, 0);
>          dup2(fd, 1);
>          /* In case -D is given do not redirect stderr to /dev/null */
> -        if (!qemu_logfile) {
> +        if (!qemu_logfile || qemu_logfile == stderr) {
>              dup2(fd, 2);
>          }
>  
> diff --git a/util/log.c b/util/log.c
> index a7ddc7e..a06aa14 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -56,7 +56,7 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
>  #ifdef CONFIG_TRACE_LOG
>      qemu_loglevel |= LOG_TRACE;
>  #endif
> -    if ((qemu_loglevel || is_daemonized()) && !qemu_logfile) {
> +    if (qemu_loglevel && !qemu_logfile) {
>          if (logfilename) {
>              qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
>              if (!qemu_logfile) {
> @@ -66,9 +66,6 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
>              /* In case we are a daemon redirect stderr to logfile */
>              if (is_daemonized()) {
>                  dup2(fileno(qemu_logfile), STDERR_FILENO);
> -                fclose(qemu_logfile);
> -                /* This will skip closing logfile in qemu_log_close() */
> -                qemu_logfile = stderr;
>              }
>          } else {
>              /* Default to stderr if no log file specified */
> @@ -89,7 +86,7 @@ void do_qemu_set_log(int log_flags, bool use_own_buffers)
>              log_append = 1;
>          }
>      }
> -    if (!qemu_loglevel && !is_daemonized() && qemu_logfile) {
> +    if (!qemu_loglevel && qemu_logfile) {
>          qemu_log_close();
>      }
>  }
>
Denis V. Lunev March 3, 2016, 1:53 p.m. UTC | #2
On 03/03/2016 04:49 PM, Paolo Bonzini wrote:
>
> On 03/03/2016 14:48, Denis V. Lunev wrote:
>> libvirt in this case spawns
>>    /usr/bin/qemu-system-x86_64 -S -no-user-config -nodefaults -nographic
>>      -M none
>>      -qmp unix:/var/lib/libvirt/qemu/capabilities.monitor.sock,server,nowait
>>      -pidfile /var/lib/libvirt/qemu/capabilities.pidfile -daemonize
>> and with CONFIG_TRACE_LOG this process hangs as stderr becomes redirected
>> to terminal (qemu_logfile == stderr). We do not have redirection to
>> /dev/null in this case which is necessary.
>>
>> Broken by:
>>      commit 96c33a4523ee1abe382ce4ff3e82b90ba78aa186
>>      Author: Dimitris Aragiorgis <dimara@arrikto.com>
>>      Date:   Thu Feb 18 13:38:38 2016 +0200
>>
>>      log: Redirect stderr to logfile if deamonized
>>
>> We should also take into account log filename change in runtime through
>> QMP/HMP, when the log could be even closed. In this case stderr should
>> be tweaked accordingly.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: Dimitris Aragiorgis <dimara@arrikto.com>
>> CC: Paolo Bonzini <pbonzini@redhat.com>
>> CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> A patch has been posted already, and I'll send a pull request tomorrow.
>
> Paolo
I have not seen it. Can you post a link?

By the way, there are other cases fixed here, thus may be some
follow up is necessary that is why I am asking.

Den
Paolo Bonzini March 3, 2016, 2:04 p.m. UTC | #3
On 03/03/2016 14:53, Denis V. Lunev wrote:
>> A patch has been posted already, and I'll send a pull request tomorrow.
>
> I have not seen it. Can you post a link?

[PATCH] log: do not log if QEMU is daemonized but without -D

but I found a missing case that your patch handles, so I'll post a v2 now.

Paolo

> By the way, there are other cases fixed here, thus may be some
> follow up is necessary that is why I am asking.
Denis V. Lunev March 3, 2016, 2:08 p.m. UTC | #4
On 03/03/2016 05:04 PM, Paolo Bonzini wrote:
>
> On 03/03/2016 14:53, Denis V. Lunev wrote:
>>> A patch has been posted already, and I'll send a pull request tomorrow.
>> I have not seen it. Can you post a link?
> [PATCH] log: do not log if QEMU is daemonized but without -D
>
> but I found a missing case that your patch handles, so I'll post a v2 now.
>
> Paolo

that is fine :) let's see. Though I think that resulted code is more
readable in my approach.

Den
Paolo Bonzini March 3, 2016, 2:15 p.m. UTC | #5
On 03/03/2016 15:08, Denis V. Lunev wrote:
> On 03/03/2016 05:04 PM, Paolo Bonzini wrote:
>>
>> On 03/03/2016 14:53, Denis V. Lunev wrote:
>>>> A patch has been posted already, and I'll send a pull request tomorrow.
>>> I have not seen it. Can you post a link?
>> [PATCH] log: do not log if QEMU is daemonized but without -D
>>
>> but I found a missing case that your patch handles, so I'll post a v2
>> now.
>>
>> Paolo
> 
> that is fine :) let's see. Though I think that resulted code is more
> readable in my approach.

Yes, I was going for the smallest change.  Cleanups can be done on top.

Actually, the patch in v1 is fine.  My worry after looking at your patch
was that I didn't have the dup2(stdout, stderr) case.  However, with my
change you can never call qemu_log_close if is_daemonized(), because
even the monitor command "logfile" cannot set logfilename to NULL.

Paolo
Denis V. Lunev March 3, 2016, 2:25 p.m. UTC | #6
On 03/03/2016 05:15 PM, Paolo Bonzini wrote:
>
> On 03/03/2016 15:08, Denis V. Lunev wrote:
>> On 03/03/2016 05:04 PM, Paolo Bonzini wrote:
>>> On 03/03/2016 14:53, Denis V. Lunev wrote:
>>>>> A patch has been posted already, and I'll send a pull request tomorrow.
>>>> I have not seen it. Can you post a link?
>>> [PATCH] log: do not log if QEMU is daemonized but without -D
>>>
>>> but I found a missing case that your patch handles, so I'll post a v2
>>> now.
>>>
>>> Paolo
>> that is fine :) let's see. Though I think that resulted code is more
>> readable in my approach.
> Yes, I was going for the smallest change.  Cleanups can be done on top.
>
> Actually, the patch in v1 is fine.  My worry after looking at your patch
> was that I didn't have the dup2(stdout, stderr) case.  However, with my
> change you can never call qemu_log_close if is_daemonized(), because
> even the monitor command "logfile" cannot set logfilename to NULL.
>
> Paolo
IMHO you are wrong.

void qemu_set_log_filename(const char *filename)
{
     g_free(logfilename);
     logfilename = g_strdup(filename);
     qemu_log_close();
     qemu_set_log(qemu_loglevel);
}

static void hmp_logfile(Monitor *mon, const QDict *qdict)
{
     qemu_set_log_filename(qdict_get_str(qdict, "filename"));
}

This means that we will have qemu_log_close()
called in ANY case, even daemonized.

 From my point of view stderr will continue to be mapped
to the old file if we request to stop logging either by
zero mask or by setting empty filename.

Den
Paolo Bonzini March 3, 2016, 2:34 p.m. UTC | #7
On 03/03/2016 15:25, Denis V. Lunev wrote:
>> Actually, the patch in v1 is fine.  My worry after looking at your patch
>> was that I didn't have the dup2(stdout, stderr) case.  However, with my
>> change you can never call qemu_log_close if is_daemonized(), because
>> even the monitor command "logfile" cannot set logfilename to NULL.
>
> IMHO you are wrong.

Possible. :)

> void qemu_set_log_filename(const char *filename)
> {
>     g_free(logfilename);
>     logfilename = g_strdup(filename);
>     qemu_log_close();
>     qemu_set_log(qemu_loglevel);
> }
> 
> static void hmp_logfile(Monitor *mon, const QDict *qdict)
> {
>     qemu_set_log_filename(qdict_get_str(qdict, "filename"));
> }
> 
> This means that we will have qemu_log_close()
> called in ANY case, even daemonized.
> From my point of view stderr will continue to be mapped
> to the old file if we request to stop logging either by
> zero mask or by setting empty filename.

Yes, but filename will never be NULL in hmp_logfile, will it?  It's
declared as 'F' in hmp-commands.hx, not as 'F?'.  If this is changed, I
agree that the dup2 needs to be added.

A different issue is that do_qemu_set_log *exits* instead of printing an
Error if fopen fails. In my opinion, in this case logging should not
even be disabled in this case.  But it can and should be fixed separately.

The code is really ugly, it is old and used to be just a debugging aid.

Paolo
Denis V. Lunev March 3, 2016, 2:47 p.m. UTC | #8
On 03/03/2016 05:34 PM, Paolo Bonzini wrote:
>
> On 03/03/2016 15:25, Denis V. Lunev wrote:
>>> Actually, the patch in v1 is fine.  My worry after looking at your patch
>>> was that I didn't have the dup2(stdout, stderr) case.  However, with my
>>> change you can never call qemu_log_close if is_daemonized(), because
>>> even the monitor command "logfile" cannot set logfilename to NULL.
>> IMHO you are wrong.
> Possible. :)
>
>> void qemu_set_log_filename(const char *filename)
>> {
>>      g_free(logfilename);
>>      logfilename = g_strdup(filename);
>>      qemu_log_close();
>>      qemu_set_log(qemu_loglevel);
>> }
>>
>> static void hmp_logfile(Monitor *mon, const QDict *qdict)
>> {
>>      qemu_set_log_filename(qdict_get_str(qdict, "filename"));
>> }
>>
>> This means that we will have qemu_log_close()
>> called in ANY case, even daemonized.
>>  From my point of view stderr will continue to be mapped
>> to the old file if we request to stop logging either by
>> zero mask or by setting empty filename.
> Yes, but filename will never be NULL in hmp_logfile, will it?  It's
> declared as 'F' in hmp-commands.hx, not as 'F?'.  If this is changed, I
> agree that the dup2 needs to be added.
>
> A different issue is that do_qemu_set_log *exits* instead of printing an
> Error if fopen fails. In my opinion, in this case logging should not
> even be disabled in this case.  But it can and should be fixed separately.
>
> The code is really ugly, it is old and used to be just a debugging aid.
>
> Paolo
ok, you are finally right. Your original code is correct and will
work even in these corner case.

Will it make sense to send a patch which will replace that code
to my one as followup + fix if 'fopen' will fail?

Den
Paolo Bonzini March 3, 2016, 2:53 p.m. UTC | #9
On 03/03/2016 15:47, Denis V. Lunev wrote:
>>
> ok, you are finally right. Your original code is correct and will
> work even in these corner case.
> 
> Will it make sense to send a patch which will replace that code
> to my one as followup + fix if 'fopen' will fail?

Definitely.  While at it, you could move qemu_log_close and
qemu_log_flush from the header to the C file.  They are in the header
only for very historical reasons; exec.c in the past could only invoke a
limited amount of external code, but luckily that's not the case anymore.

Paolo
Denis V. Lunev March 3, 2016, 2:55 p.m. UTC | #10
On 03/03/2016 05:53 PM, Paolo Bonzini wrote:
>
> On 03/03/2016 15:47, Denis V. Lunev wrote:
>> ok, you are finally right. Your original code is correct and will
>> work even in these corner case.
>>
>> Will it make sense to send a patch which will replace that code
>> to my one as followup + fix if 'fopen' will fail?
> Definitely.  While at it, you could move qemu_log_close and
> qemu_log_flush from the header to the C file.  They are in the header
> only for very historical reasons; exec.c in the past could only invoke a
> limited amount of external code, but luckily that's not the case anymore.
>
> Paolo
got this. thank you :)

Patch
diff mbox

diff --git a/include/qemu/log.h b/include/qemu/log.h
index dda65fd..8083f82 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -92,6 +92,10 @@  static inline void qemu_log_close(void)
         }
         qemu_logfile = NULL;
     }
+
+    if (is_daemonized()) {
+        dup2(STDOUT_FILENO, STDERR_FILENO); /* dup /dev/null to stderr */
+    }
 }
 
 /* define log items */
diff --git a/os-posix.c b/os-posix.c
index 92fa3ba..d4b2a91 100644
--- a/os-posix.c
+++ b/os-posix.c
@@ -277,7 +277,7 @@  void os_setup_post(void)
         dup2(fd, 0);
         dup2(fd, 1);
         /* In case -D is given do not redirect stderr to /dev/null */
-        if (!qemu_logfile) {
+        if (!qemu_logfile || qemu_logfile == stderr) {
             dup2(fd, 2);
         }
 
diff --git a/util/log.c b/util/log.c
index a7ddc7e..a06aa14 100644
--- a/util/log.c
+++ b/util/log.c
@@ -56,7 +56,7 @@  void do_qemu_set_log(int log_flags, bool use_own_buffers)
 #ifdef CONFIG_TRACE_LOG
     qemu_loglevel |= LOG_TRACE;
 #endif
-    if ((qemu_loglevel || is_daemonized()) && !qemu_logfile) {
+    if (qemu_loglevel && !qemu_logfile) {
         if (logfilename) {
             qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
             if (!qemu_logfile) {
@@ -66,9 +66,6 @@  void do_qemu_set_log(int log_flags, bool use_own_buffers)
             /* In case we are a daemon redirect stderr to logfile */
             if (is_daemonized()) {
                 dup2(fileno(qemu_logfile), STDERR_FILENO);
-                fclose(qemu_logfile);
-                /* This will skip closing logfile in qemu_log_close() */
-                qemu_logfile = stderr;
             }
         } else {
             /* Default to stderr if no log file specified */
@@ -89,7 +86,7 @@  void do_qemu_set_log(int log_flags, bool use_own_buffers)
             log_append = 1;
         }
     }
-    if (!qemu_loglevel && !is_daemonized() && qemu_logfile) {
+    if (!qemu_loglevel && qemu_logfile) {
         qemu_log_close();
     }
 }