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@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

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list

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@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.
--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list

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@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@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.
>
--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list