3:02 a.m.
Libvirt logs include many snippets for debugging daemon state, but
some of those messages are either missing vital information or end up logging
"errors" for normal operating conditions as well.
This series improves log messages, also adding additional WARN'ings for
connection instantiation and closure.
Prerna Saxena (3):
Debug: Add WARN'ing messages for when a client has opened/closed
connection.
Debug: Remove unnecessary errors reported while parsing non-existent
sysfs files.
Debug: Report VM errors more concisely.
src/qemu/qemu_process.c | 4 ++--
src/rpc/virnetserverclient.c | 18 ++++++++++++++----
src/util/virnetdev.c | 2 +-
3 files changed, 17 insertions(+), 7 deletions(-)
--
1.8.1.2
3:02 a.m.
New subject: [libvirt] [PATCH 1/3] Debug: Add WARN'ing messages for when a client has opened/closed connection.
While tracing connections from a remote client, it helps to keep track
of the connection lifecycle. Messages such as the following :
error : virNetSocketReadWire:1574 : End of file while reading data: Input/output error
are rather unhelpful. They do not indicate if the client had earlier asked for
connection closure via libvirt API.
This patch introduces messages to annotate when a client connected/disconnected.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/rpc/virnetserverclient.c | 18 ++++++++++++++----
1 file changed, 14 insertions(+), 4 deletions(-)
diff --git a/src/rpc/virnetserverclient.c b/src/rpc/virnetserverclient.c
index 85857bc..a77feaa 100644
--- a/src/rpc/virnetserverclient.c
+++ b/src/rpc/virnetserverclient.c
@@ -678,14 +678,19 @@ int virNetServerClientGetTLSKeySize(virNetServerClientPtr client)
return size;
}
#endif
-
+/*
+ * This mostly just needs to publish the client socket FD to logs.
+ * It does not necessarily need a lock, or will add lock contention problems.
+ * Replace the lock with a reference counting mechanism, to prevent the client
+ * object from being deallocated while this is being run
+ */
int virNetServerClientGetFD(virNetServerClientPtr client)
{
int fd = -1;
- virObjectLock(client);
+ virObjectRef(client);
if (client->sock)
fd = virNetSocketGetFD(client->sock);
- virObjectUnlock(client);
+ virObjectUnref(client);
return fd;
}
@@ -965,7 +970,9 @@ void virNetServerClientClose(virNetServerClientPtr client)
virKeepAlivePtr ka;
virObjectLock(client);
- VIR_DEBUG("client=%p", client);
+ VIR_WARN("Free'ing up resources for client=%p sock=%d", client,
+ virNetServerClientGetFD(client));
+
if (!client->sock) {
virObjectUnlock(client);
return;
@@ -1039,6 +1046,8 @@ void virNetServerClientDelayedClose(virNetServerClientPtr client)
virObjectLock(client);
client->delayedClose = true;
virObjectUnlock(client);
+ VIR_WARN("Client=%p sock=%d requested closure of connection.",
+ client, virNetServerClientGetFD(client));
}
void virNetServerClientImmediateClose(virNetServerClientPtr client)
@@ -1151,6 +1160,7 @@ static void virNetServerClientDispatchRead(virNetServerClientPtr
client)
if (client->rx->nfds == 0) {
if (virNetServerClientRead(client) < 0) {
client->wantClose = true;
+ VIR_WARN("Client=%p sock=%p closed connection", client,
client->sock);
return; /* Error */
}
}
--
1.8.1.2
3:11 a.m.
New subject: [libvirt] [PATCH 1/3] Debug: Add WARN'ing messages for when a client has opened/closed connection.
On Wed, Mar 22, 2017 at 01:02:17 -0700, Prerna Saxena wrote:
While tracing connections from a remote client, it helps to keep
track
of the connection lifecycle. Messages such as the following :
error : virNetSocketReadWire:1574 : End of file while reading data: Input/output error
are rather unhelpful. They do not indicate if the client had earlier asked for
connection closure via libvirt API.
This patch introduces messages to annotate when a client connected/disconnected.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/rpc/virnetserverclient.c | 18 ++++++++++++++----
1 file changed, 14 insertions(+), 4 deletions(-)
diff --git a/src/rpc/virnetserverclient.c b/src/rpc/virnetserverclient.c
index 85857bc..a77feaa 100644
--- a/src/rpc/virnetserverclient.c
+++ b/src/rpc/virnetserverclient.c
@@ -678,14 +678,19 @@ int virNetServerClientGetTLSKeySize(virNetServerClientPtr client)
return size;
}
#endif
-
+/*
+ * This mostly just needs to publish the client socket FD to logs.
+ * It does not necessarily need a lock, or will add lock contention problems.
+ * Replace the lock with a reference counting mechanism, to prevent the client
+ * object from being deallocated while this is being run
+ */
int virNetServerClientGetFD(virNetServerClientPtr client)
{
int fd = -1;
- virObjectLock(client);
+ virObjectRef(client);
if (client->sock)
fd = virNetSocketGetFD(client->sock);
- virObjectUnlock(client);
+ virObjectUnref(client);
This change is not justified in any way. Also looks wrong. You can't
access an unlocked object.
return fd;
}
@@ -965,7 +970,9 @@ void virNetServerClientClose(virNetServerClientPtr client)
virKeepAlivePtr ka;
virObjectLock(client);
- VIR_DEBUG("client=%p", client);
+ VIR_WARN("Free'ing up resources for client=%p sock=%d", client,
+ virNetServerClientGetFD(client));
NACK using warnings instead of debug messages is not desired. For debug
purposes you should use debug logs.
3:58 a.m.
New subject: [libvirt] [PATCH 1/3] Debug: Add WARN'ing messages for when a client has opened/closed connection.
I looked through what you were suggesting.
I was assuming virNetSocketGetFD()would do a NULL check for the sock arg,
and would return immediately if a different client executed a
virNetServerClientClose() setting client->sock to null.
Since this check is missing, I understand the implicit assumption is to
always have virNetServerClientGetFD() lock the client, and consequently, I
will rearrange debug messages around to prevent lock contention.
Sending out a V2.
On Wed, Mar 22, 2017 at 1:41 PM, Peter Krempa <pkrempa(a)redhat.com> wrote:
On Wed, Mar 22, 2017 at 01:02:17 -0700, Prerna Saxena wrote:
> While tracing connections from a remote client, it helps to keep track
> of the connection lifecycle. Messages such as the following :
>
> error : virNetSocketReadWire:1574 : End of file while reading data:
Input/output error
>
> are rather unhelpful. They do not indicate if the client had earlier
asked for
> connection closure via libvirt API.
> This patch introduces messages to annotate when a client
connected/disconnected.
>
> Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
> ---
> src/rpc/virnetserverclient.c | 18 ++++++++++++++----
> 1 file changed, 14 insertions(+), 4 deletions(-)
>
> diff --git a/src/rpc/virnetserverclient.c b/src/rpc/virnetserverclient.c
> index 85857bc..a77feaa 100644
> --- a/src/rpc/virnetserverclient.c
> +++ b/src/rpc/virnetserverclient.c
> @@ -678,14 +678,19 @@ int virNetServerClientGetTLSKeySize(virNetServerClientPtr
client)
> return size;
> }
> #endif
> -
> +/*
> + * This mostly just needs to publish the client socket FD to logs.
> + * It does not necessarily need a lock, or will add lock contention
problems.
> + * Replace the lock with a reference counting mechanism, to prevent the
client
> + * object from being deallocated while this is being run
> + */
> int virNetServerClientGetFD(virNetServerClientPtr client)
> {
> int fd = -1;
> - virObjectLock(client);
> + virObjectRef(client);
> if (client->sock)
> fd = virNetSocketGetFD(client->sock);
> - virObjectUnlock(client);
> + virObjectUnref(client);
This change is not justified in any way. Also looks wrong. You can't
access an unlocked object.
> return fd;
> }
>
> @@ -965,7 +970,9 @@ void virNetServerClientClose(virNetServerClientPtr
client)
> virKeepAlivePtr ka;
>
> virObjectLock(client);
> - VIR_DEBUG("client=%p", client);
> + VIR_WARN("Free'ing up resources for client=%p sock=%d", client,
> + virNetServerClientGetFD(client));
NACK using warnings instead of debug messages is not desired. For debug
purposes you should use debug logs.
3:02 a.m.
New subject: [libvirt] [PATCH 2/3] Debug: Remove unnecessary errors reported while parsing non-existent sysfs files.
Sample from current logs:
error : virFileReadAll:1290 : Failed to open file '/sys/class/net/tap3/operstate':
No such file or directory
error : virNetDevGetLinkInfo:1895 : unable to read: /sys/class/net/tap3/operstate: No such
file or directory
These have no useful data point and are redundant.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/util/virnetdev.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/util/virnetdev.c b/src/util/virnetdev.c
index d123248..3e2f962 100644
--- a/src/util/virnetdev.c
+++ b/src/util/virnetdev.c
@@ -1874,7 +1874,7 @@ virNetDevGetLinkInfo(const char *ifname,
if (virNetDevSysfsFile(&path, ifname, "operstate") < 0)
goto cleanup;
- if (virFileReadAll(path, 1024, &buf) < 0) {
+ if (virFileReadAllQuiet(path, 1024, &buf) < 0 && errno != ENOENT) {
virReportSystemError(errno,
_("unable to read: %s"),
path);
--
1.8.1.2
3:14 a.m.
New subject: [libvirt] [PATCH 2/3] Debug: Remove unnecessary errors reported while parsing non-existent sysfs files.
On Wed, Mar 22, 2017 at 01:02:18 -0700, Prerna Saxena wrote:
Sample from current logs:
error : virFileReadAll:1290 : Failed to open file
'/sys/class/net/tap3/operstate': No such file or directory
error : virNetDevGetLinkInfo:1895 : unable to read: /sys/class/net/tap3/operstate: No
such file or directory
These have no useful data point and are redundant.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/util/virnetdev.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/util/virnetdev.c b/src/util/virnetdev.c
index d123248..3e2f962 100644
--- a/src/util/virnetdev.c
+++ b/src/util/virnetdev.c
@@ -1874,7 +1874,7 @@ virNetDevGetLinkInfo(const char *ifname,
if (virNetDevSysfsFile(&path, ifname, "operstate") < 0)
goto cleanup;
- if (virFileReadAll(path, 1024, &buf) < 0) {
+ if (virFileReadAllQuiet(path, 1024, &buf) < 0 && errno != ENOENT) {
virReportSystemError(errno,
_("unable to read: %s"),
path);
Remove this message here instead of switching to virFileReadAllQuiet.
virFileReadAll reports messages according to the failure itself.
3:26 a.m.
New subject: [libvirt] [PATCH 2/3] Debug: Remove unnecessary errors reported while parsing non-existent sysfs files.
On Wed, Mar 22, 2017 at 09:14:41 +0100, Peter Krempa wrote:
On Wed, Mar 22, 2017 at 01:02:18 -0700, Prerna Saxena wrote:
> Sample from current logs:
> error : virFileReadAll:1290 : Failed to open file
'/sys/class/net/tap3/operstate': No such file or directory
> error : virNetDevGetLinkInfo:1895 : unable to read: /sys/class/net/tap3/operstate:
No such file or directory
>
> These have no useful data point and are redundant.
>
> Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
> ---
> src/util/virnetdev.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/src/util/virnetdev.c b/src/util/virnetdev.c
> index d123248..3e2f962 100644
> --- a/src/util/virnetdev.c
> +++ b/src/util/virnetdev.c
> @@ -1874,7 +1874,7 @@ virNetDevGetLinkInfo(const char *ifname,
> if (virNetDevSysfsFile(&path, ifname, "operstate") < 0)
> goto cleanup;
>
> - if (virFileReadAll(path, 1024, &buf) < 0) {
> + if (virFileReadAllQuiet(path, 1024, &buf) < 0 && errno !=
ENOENT) {
> virReportSystemError(errno,
> _("unable to read: %s"),
> path);
Remove this message here instead of switching to virFileReadAllQuiet.
virFileReadAll reports messages according to the failure itself.
Hmm, So you want to avoid the error message altogether. So in that case
you should rather call virFileAccess and also note what happens in an
comment.
Additionally since that would be a semantic change you need to mention
it in the commit message and also make sure that all callers would
ignore such failure. Otherwise you may cause a regression where we'd
report an "unknown error" in cases where it was actually necessary.
Since I found at least one code path that propagates the error
(nodeDeviceGetXMLDesc) you should re-evaluate your approach.
3:43 a.m.
New subject: [libvirt] [PATCH 2/3] Debug: Remove unnecessary errors reported while parsing non-existent sysfs files.
I agree. Thanks for pointing out that this is a behavioural change, which
should not happen.
I should be doing something like this:
if (virFileReadAllQuiet(path, 1024, &buf) < 0 ) {
if (errno != ENOENT) {
virReportSystemError(errno,
_("unable to read: %s"), path);
}
goto cleanup;
}
On Wed, Mar 22, 2017 at 1:56 PM, Peter Krempa <pkrempa(a)redhat.com> wrote:
On Wed, Mar 22, 2017 at 09:14:41 +0100, Peter Krempa wrote:
> On Wed, Mar 22, 2017 at 01:02:18 -0700, Prerna Saxena wrote:
> > Sample from current logs:
> > error : virFileReadAll:1290 : Failed to open file
'/sys/class/net/tap3/operstate':
No such file or directory
> > error : virNetDevGetLinkInfo:1895 : unable to read:
/sys/class/net/tap3/operstate: No such file or directory
> >
> > These have no useful data point and are redundant.
> >
> > Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
> > ---
> > src/util/virnetdev.c | 2 +-
> > 1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/src/util/virnetdev.c b/src/util/virnetdev.c
> > index d123248..3e2f962 100644
> > --- a/src/util/virnetdev.c
> > +++ b/src/util/virnetdev.c
> > @@ -1874,7 +1874,7 @@ virNetDevGetLinkInfo(const char *ifname,
> > if (virNetDevSysfsFile(&path, ifname, "operstate") < 0)
> > goto cleanup;
> >
> > - if (virFileReadAll(path, 1024, &buf) < 0) {
> > + if (virFileReadAllQuiet(path, 1024, &buf) < 0 && errno !=
ENOENT)
{
> > virReportSystemError(errno,
> > _("unable to read: %s"),
> > path);
>
> Remove this message here instead of switching to virFileReadAllQuiet.
> virFileReadAll reports messages according to the failure itself.
Hmm, So you want to avoid the error message altogether. So in that case
you should rather call virFileAccess and also note what happens in an
comment.
Additionally since that would be a semantic change you need to mention
it in the commit message and also make sure that all callers would
ignore such failure. Otherwise you may cause a regression where we'd
report an "unknown error" in cases where it was actually necessary.
Since I found at least one code path that propagates the error
(nodeDeviceGetXMLDesc) you should re-evaluate your approach.
4:02 a.m.
New subject: [libvirt] [PATCH 2/3] Debug: Remove unnecessary errors reported while parsing non-existent sysfs files.
On Wed, Mar 22, 2017 at 14:13:25 +0530, Prerna wrote:
I agree. Thanks for pointing out that this is a behavioural change,
which
should not happen.
Please don't top post on technical lists.
I should be doing something like this:
if (virFileReadAllQuiet(path, 1024, &buf) < 0 ) {
if (errno != ENOENT) {
virReportSystemError(errno,
_("unable to read: %s"), path);
}
goto cleanup;
}
No, that still would break at least the one case I've pointed out below
[1].
You need to make sure that callers are okay with such change. Or you
need to find out the code path to the message you want to get rid of.
But doing this chagne without regards to odther code paths is not the
right approach.
On Wed, Mar 22, 2017 at 1:56 PM, Peter Krempa <pkrempa(a)redhat.com> wrote:
> On Wed, Mar 22, 2017 at 09:14:41 +0100, Peter Krempa wrote:
> > On Wed, Mar 22, 2017 at 01:02:18 -0700, Prerna Saxena wrote:
> > > Sample from current logs:
> > > error : virFileReadAll:1290 : Failed to open file
'/sys/class/net/tap3/operstate':
> No such file or directory
> > > error : virNetDevGetLinkInfo:1895 : unable to read:
> /sys/class/net/tap3/operstate: No such file or directory
> > >
> > > These have no useful data point and are redundant.
> > >
> > > Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
> > > ---
> > > src/util/virnetdev.c | 2 +-
> > > 1 file changed, 1 insertion(+), 1 deletion(-)
> > >
> > > diff --git a/src/util/virnetdev.c b/src/util/virnetdev.c
> > > index d123248..3e2f962 100644
> > > --- a/src/util/virnetdev.c
> > > +++ b/src/util/virnetdev.c
> > > @@ -1874,7 +1874,7 @@ virNetDevGetLinkInfo(const char *ifname,
> > > if (virNetDevSysfsFile(&path, ifname, "operstate") <
0)
> > > goto cleanup;
> > >
> > > - if (virFileReadAll(path, 1024, &buf) < 0) {
> > > + if (virFileReadAllQuiet(path, 1024, &buf) < 0 && errno
!= ENOENT)
> {
> > > virReportSystemError(errno,
> > > _("unable to read: %s"),
> > > path);
> >
> > Remove this message here instead of switching to virFileReadAllQuiet.
> > virFileReadAll reports messages according to the failure itself.
>
> Hmm, So you want to avoid the error message altogether. So in that case
> you should rather call virFileAccess and also note what happens in an
> comment.
>
> Additionally since that would be a semantic change you need to mention
> it in the commit message and also make sure that all callers would
> ignore such failure. Otherwise you may cause a regression where we'd
> report an "unknown error" in cases where it was actually necessary.
>
[1]
> Since I found at least one code path that propagates the error
> (nodeDeviceGetXMLDesc) you should re-evaluate your approach.
>
--
libvir-list mailing list
libvir-list(a)redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list
3:02 a.m.
New subject: [libvirt] [PATCH 3/3] Debug: Report VM errors more concisely.
Current logs:
error : qemuProcessFindDomainDiskByAlias:411 : internal error: no disk found with alias
ide0-0-0
There is no way to find which VM was seeing this error.
Makes debugging very hard, and the message itself is no good.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/qemu/qemu_process.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c
index ec0e36d..9f5bc3a 100644
--- a/src/qemu/qemu_process.c
+++ b/src/qemu/qemu_process.c
@@ -366,8 +366,8 @@ qemuProcessFindDomainDiskByAlias(virDomainObjPtr vm,
}
virReportError(VIR_ERR_INTERNAL_ERROR,
- _("no disk found with alias %s"),
- alias);
+ _("VM %s: no disk found with alias %s"),
+ vm->def->name, alias);
return NULL;
}
--
1.8.1.2
3:12 a.m.
New subject: [libvirt] [PATCH 3/3] Debug: Report VM errors more concisely.
On Wed, Mar 22, 2017 at 01:02:19 -0700, Prerna Saxena wrote:
Current logs:
error : qemuProcessFindDomainDiskByAlias:411 : internal error: no disk found with alias
ide0-0-0
There is no way to find which VM was seeing this error.
Makes debugging very hard, and the message itself is no good.
Signed-off-by: Prerna Saxena <saxenap.ltc(a)gmail.com>
---
src/qemu/qemu_process.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/qemu/qemu_process.c b/src/qemu/qemu_process.c
index ec0e36d..9f5bc3a 100644
--- a/src/qemu/qemu_process.c
+++ b/src/qemu/qemu_process.c
@@ -366,8 +366,8 @@ qemuProcessFindDomainDiskByAlias(virDomainObjPtr vm,
}
virReportError(VIR_ERR_INTERNAL_ERROR,
- _("no disk found with alias %s"),
- alias);
+ _("VM %s: no disk found with alias %s"),
+ vm->def->name, alias);
I think a better option is to enable debug logs anyways. This message
won't really help you debug the issue if you don't get the additional
data from where the problem happened.
2802
days inactive
2802
days old
10 comments
3 participants
participants (3)
-
Peter Krempa -
Prerna -
Prerna Saxena