ui: add tracing of VNC authentication process

Trace anything related to authentication in the VNC protocol
handshake

Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Message-id: 20170921121528.23935-3-berrange@redhat.com
Signed-off-by: Gerd Hoffmann <kraxel@redhat.com>

ui/trace-events

@@ -35,6 +35,21 @@ vnc_client_connect(void *state, void *ioc) "VNC client connect state=%p ioc=%p"
 vnc_client_disconnect_start(void *state, void *ioc) "VNC client disconnect start state=%p ioc=%p"
 vnc_client_disconnect_finish(void *state, void *ioc) "VNC client disconnect finish state=%p ioc=%p"
 vnc_client_io_wrap(void *state, void *ioc, const char *type) "VNC client I/O wrap state=%p ioc=%p type=%s"
+vnc_auth_init(void *display, int websock, int auth, int subauth) "VNC auth init state=%p websock=%d auth=%d subauth=%d"
+vnc_auth_start(void *state, int method) "VNC client auth start state=%p method=%d"
+vnc_auth_pass(void *state, int method) "VNC client auth passed state=%p method=%d"
+vnc_auth_fail(void *state, int method, const char *message, const char *reason) "VNC client auth failed state=%p method=%d message=%s reason=%s"
+vnc_auth_reject(void *state, int expect, int got) "VNC client auth rejected state=%p method expected=%d got=%d"
+vnc_auth_vencrypt_version(void *state, int major, int minor) "VNC client auth vencrypt version state=%p major=%d minor=%d"
+vnc_auth_vencrypt_subauth(void *state, int auth) "VNC client auth vencrypt subauth state=%p auth=%d"
+vnc_auth_sasl_mech_list(void *state, const char *mechs) "VNC client auth SASL state=%p mechlist=%s"
+vnc_auth_sasl_mech_choose(void *state, const char *mech) "VNC client auth SASL state=%p mech=%s"
+vnc_auth_sasl_start(void *state, const void *clientdata, size_t clientlen, const void *serverdata, size_t severlen, int ret) "VNC client auth SASL start state=%p clientdata=%p clientlen=%zu serverdata=%p serverlen=%zu ret=%d"
+vnc_auth_sasl_step(void *state, const void *clientdata, size_t clientlen, const void *serverdata, size_t severlen, int ret) "VNC client auth SASL step state=%p clientdata=%p clientlen=%zu serverdata=%p serverlen=%zu ret=%d"
+vnc_auth_sasl_ssf(void *state, int ssf) "VNC client auth SASL SSF state=%p size=%d"
+vnc_auth_sasl_username(void *state, const char *name) "VNC client auth SASL user state=%p name=%s"
+vnc_auth_sasl_acl(void *state, int allow) "VNC client auth SASL ACL state=%p allow=%d"
+
 
 # ui/input.c
 input_event_key_number(int conidx, int number, const char *qcode, bool down) "con %d, key number 0x%x [%s], down %d"

ui/vnc-auth-sasl.c

@@ -25,6 +25,7 @@
 #include "qemu/osdep.h"
 #include "qapi/error.h"
 #include "vnc.h"
+#include "trace.h"
 
 /* Max amount of data we send/recv for SASL steps to prevent DOS */
 #define SASL_DATA_MAX_LEN (1024 * 1024)
@@ -133,27 +134,26 @@ static int vnc_auth_sasl_check_access(VncState *vs)
 
     err = sasl_getprop(vs->sasl.conn, SASL_USERNAME, &val);
     if (err != SASL_OK) {
-        VNC_DEBUG("cannot query SASL username on connection %d (%s), denying access\n",
-                  err, sasl_errstring(err, NULL, NULL));
+        trace_vnc_auth_fail(vs, vs->auth, "Cannot fetch SASL username",
+                            sasl_errstring(err, NULL, NULL));
         return -1;
     }
     if (val == NULL) {
-        VNC_DEBUG("no client username was found, denying access\n");
+        trace_vnc_auth_fail(vs, vs->auth, "No SASL username set", "");
         return -1;
     }
-    VNC_DEBUG("SASL client username %s\n", (const char *)val);
 
     vs->sasl.username = g_strdup((const char*)val);
+    trace_vnc_auth_sasl_username(vs, vs->sasl.username);
 
     if (vs->vd->sasl.acl == NULL) {
-        VNC_DEBUG("no ACL activated, allowing access\n");
+        trace_vnc_auth_sasl_acl(vs, 1);
         return 0;
     }
 
     allow = qemu_acl_party_is_allowed(vs->vd->sasl.acl, vs->sasl.username);
 
-    VNC_DEBUG("SASL client %s %s by ACL\n", vs->sasl.username,
-              allow ? "allowed" : "denied");
+    trace_vnc_auth_sasl_acl(vs, allow);
     return allow ? 0 : -1;
 }
 
@@ -170,7 +170,9 @@ static int vnc_auth_sasl_check_ssf(VncState *vs)
         return 0;
 
     ssf = *(const int *)val;
-    VNC_DEBUG("negotiated an SSF of %d\n", ssf);
+
+    trace_vnc_auth_sasl_ssf(vs, ssf);
+
     if (ssf < 56)
         return 0; /* 56 is good for Kerberos */
 
@@ -218,33 +220,28 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le
         datalen--; /* Don't count NULL byte when passing to _start() */
     }
 
-    VNC_DEBUG("Step using SASL Data %p (%d bytes)\n",
-              clientdata, datalen);
     err = sasl_server_step(vs->sasl.conn,
                            clientdata,
                            datalen,
                            &serverout,
                            &serveroutlen);
+    trace_vnc_auth_sasl_step(vs, data, len, serverout, serveroutlen, err);
     if (err != SASL_OK &&
         err != SASL_CONTINUE) {
-        VNC_DEBUG("sasl step failed %d (%s)\n",
-                  err, sasl_errdetail(vs->sasl.conn));
+        trace_vnc_auth_fail(vs, vs->auth, "Cannot step SASL auth",
+                            sasl_errdetail(vs->sasl.conn));
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
     }
 
     if (serveroutlen > SASL_DATA_MAX_LEN) {
-        VNC_DEBUG("sasl step reply data too long %d\n",
-                  serveroutlen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL data too long", "");
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
     }
 
-    VNC_DEBUG("SASL return data %d bytes, nil; %d\n",
-              serveroutlen, serverout ? 0 : 1);
-
     if (serveroutlen) {
         vnc_write_u32(vs, serveroutlen + 1);
         vnc_write(vs, serverout, serveroutlen + 1);
@@ -256,22 +253,20 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le
     vnc_write_u8(vs, err == SASL_CONTINUE ? 0 : 1);
 
     if (err == SASL_CONTINUE) {
-        VNC_DEBUG("%s", "Authentication must continue\n");
         /* Wait for step length */
         vnc_read_when(vs, protocol_client_auth_sasl_step_len, 4);
     } else {
         if (!vnc_auth_sasl_check_ssf(vs)) {
-            VNC_DEBUG("Authentication rejected for weak SSF %p\n", vs->ioc);
+            trace_vnc_auth_fail(vs, vs->auth, "SASL SSF too weak", "");
             goto authreject;
         }
 
         /* Check username whitelist ACL */
         if (vnc_auth_sasl_check_access(vs) < 0) {
-            VNC_DEBUG("Authentication rejected for ACL %p\n", vs->ioc);
             goto authreject;
         }
 
-        VNC_DEBUG("Authentication successful %p\n", vs->ioc);
+        trace_vnc_auth_pass(vs, vs->auth);
         vnc_write_u32(vs, 0); /* Accept auth */
         /*
          * Delay writing in SSF encoded mode until pending output
@@ -300,9 +295,9 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le
 static int protocol_client_auth_sasl_step_len(VncState *vs, uint8_t *data, size_t len)
 {
     uint32_t steplen = read_u32(data, 0);
-    VNC_DEBUG("Got client step len %d\n", steplen);
+
     if (steplen > SASL_DATA_MAX_LEN) {
-        VNC_DEBUG("Too much SASL data %d\n", steplen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL step len too large", "");
         vnc_client_error(vs);
         return -1;
     }
@@ -346,33 +341,28 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l
         datalen--; /* Don't count NULL byte when passing to _start() */
     }
 
-    VNC_DEBUG("Start SASL auth with mechanism %s. Data %p (%d bytes)\n",
-              vs->sasl.mechlist, clientdata, datalen);
     err = sasl_server_start(vs->sasl.conn,
                             vs->sasl.mechlist,
                             clientdata,
                             datalen,
                             &serverout,
                             &serveroutlen);
+    trace_vnc_auth_sasl_start(vs, data, len, serverout, serveroutlen, err);
     if (err != SASL_OK &&
         err != SASL_CONTINUE) {
-        VNC_DEBUG("sasl start failed %d (%s)\n",
-                  err, sasl_errdetail(vs->sasl.conn));
+        trace_vnc_auth_fail(vs, vs->auth, "Cannot start SASL auth",
+                            sasl_errdetail(vs->sasl.conn));
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
     }
     if (serveroutlen > SASL_DATA_MAX_LEN) {
-        VNC_DEBUG("sasl start reply data too long %d\n",
-                  serveroutlen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL data too long", "");
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
     }
 
-    VNC_DEBUG("SASL return data %d bytes, nil; %d\n",
-              serveroutlen, serverout ? 0 : 1);
-
     if (serveroutlen) {
         vnc_write_u32(vs, serveroutlen + 1);
         vnc_write(vs, serverout, serveroutlen + 1);
@@ -384,22 +374,20 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l
     vnc_write_u8(vs, err == SASL_CONTINUE ? 0 : 1);
 
     if (err == SASL_CONTINUE) {
-        VNC_DEBUG("%s", "Authentication must continue\n");
         /* Wait for step length */
         vnc_read_when(vs, protocol_client_auth_sasl_step_len, 4);
     } else {
         if (!vnc_auth_sasl_check_ssf(vs)) {
-            VNC_DEBUG("Authentication rejected for weak SSF %p\n", vs->ioc);
+            trace_vnc_auth_fail(vs, vs->auth, "SASL SSF too weak", "");
             goto authreject;
         }
 
         /* Check username whitelist ACL */
         if (vnc_auth_sasl_check_access(vs) < 0) {
-            VNC_DEBUG("Authentication rejected for ACL %p\n", vs->ioc);
             goto authreject;
         }
 
-        VNC_DEBUG("Authentication successful %p\n", vs->ioc);
+        trace_vnc_auth_pass(vs, vs->auth);
         vnc_write_u32(vs, 0); /* Accept auth */
         start_client_init(vs);
     }
@@ -422,9 +410,9 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l
 static int protocol_client_auth_sasl_start_len(VncState *vs, uint8_t *data, size_t len)
 {
     uint32_t startlen = read_u32(data, 0);
-    VNC_DEBUG("Got client start len %d\n", startlen);
+
     if (startlen > SASL_DATA_MAX_LEN) {
-        VNC_DEBUG("Too much SASL data %d\n", startlen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL start len too large", "");
         vnc_client_error(vs);
         return -1;
     }
@@ -439,22 +427,18 @@ static int protocol_client_auth_sasl_start_len(VncState *vs, uint8_t *data, size
 static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_t len)
 {
     char *mechname = g_strndup((const char *) data, len);
-    VNC_DEBUG("Got client mechname '%s' check against '%s'\n",
-              mechname, vs->sasl.mechlist);
+    trace_vnc_auth_sasl_mech_choose(vs, mechname);
 
     if (strncmp(vs->sasl.mechlist, mechname, len) == 0) {
         if (vs->sasl.mechlist[len] != '\0' &&
             vs->sasl.mechlist[len] != ',') {
-            VNC_DEBUG("One %d", vs->sasl.mechlist[len]);
             goto fail;
         }
     } else {
         char *offset = strstr(vs->sasl.mechlist, mechname);
-        VNC_DEBUG("Two %p\n", offset);
         if (!offset) {
             goto fail;
         }
-        VNC_DEBUG("Two '%s'\n", offset);
         if (offset[-1] != ',' ||
             (offset[len] != '\0'&&
              offset[len] != ',')) {
@@ -465,11 +449,11 @@ static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_
     g_free(vs->sasl.mechlist);
     vs->sasl.mechlist = mechname;
 
-    VNC_DEBUG("Validated mechname '%s'\n", mechname);
     vnc_read_when(vs, protocol_client_auth_sasl_start_len, 4);
     return 0;
 
  fail:
+    trace_vnc_auth_fail(vs, vs->auth, "Unsupported mechname", mechname);
     vnc_client_error(vs);
     g_free(mechname);
     return -1;
@@ -478,14 +462,14 @@ static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_
 static int protocol_client_auth_sasl_mechname_len(VncState *vs, uint8_t *data, size_t len)
 {
     uint32_t mechlen = read_u32(data, 0);
-    VNC_DEBUG("Got client mechname len %d\n", mechlen);
+
     if (mechlen > 100) {
-        VNC_DEBUG("Too long SASL mechname data %d\n", mechlen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL mechname too long", "");
         vnc_client_error(vs);
         return -1;
     }
     if (mechlen < 1) {
-        VNC_DEBUG("Too short SASL mechname %d\n", mechlen);
+        trace_vnc_auth_fail(vs, vs->auth, "SASL mechname too short", "");
         vnc_client_error(vs);
         return -1;
     }
@@ -524,19 +508,22 @@ void start_auth_sasl(VncState *vs)
     const char *mechlist = NULL;
     sasl_security_properties_t secprops;
     int err;
+    Error *local_err = NULL;
     char *localAddr, *remoteAddr;
     int mechlistlen;
 
-    VNC_DEBUG("Initialize SASL auth %p\n", vs->ioc);
-
     /* Get local & remote client addresses in form  IPADDR;PORT */
-    localAddr = vnc_socket_ip_addr_string(vs->sioc, true, NULL);
+    localAddr = vnc_socket_ip_addr_string(vs->sioc, true, &local_err);
     if (!localAddr) {
+        trace_vnc_auth_fail(vs, vs->auth, "Cannot format local IP",
+                            error_get_pretty(local_err));
         goto authabort;
     }
 
-    remoteAddr = vnc_socket_ip_addr_string(vs->sioc, false, NULL);
+    remoteAddr = vnc_socket_ip_addr_string(vs->sioc, false, &local_err);
     if (!remoteAddr) {
+        trace_vnc_auth_fail(vs, vs->auth, "Cannot format remote IP",
+                            error_get_pretty(local_err));
         g_free(localAddr);
         goto authabort;
     }
@@ -554,8 +541,8 @@ void start_auth_sasl(VncState *vs)
     localAddr = remoteAddr = NULL;
 
     if (err != SASL_OK) {
-        VNC_DEBUG("sasl context setup failed %d (%s)",
-                  err, sasl_errstring(err, NULL, NULL));
+        trace_vnc_auth_fail(vs, vs->auth,  "SASL context setup failed",
+                            sasl_errstring(err, NULL, NULL));
         vs->sasl.conn = NULL;
         goto authabort;
     }
@@ -570,8 +557,8 @@ void start_auth_sasl(VncState *vs)
         keysize = qcrypto_tls_session_get_key_size(vs->tls,
                                                    &local_err);
         if (keysize < 0) {
-            VNC_DEBUG("cannot TLS get cipher size: %s\n",
-                      error_get_pretty(local_err));
+            trace_vnc_auth_fail(vs, vs->auth, "cannot TLS get cipher size",
+                                error_get_pretty(local_err));
             error_free(local_err);
             sasl_dispose(&vs->sasl.conn);
             vs->sasl.conn = NULL;
@@ -581,8 +568,8 @@ void start_auth_sasl(VncState *vs)
 
         err = sasl_setprop(vs->sasl.conn, SASL_SSF_EXTERNAL, &ssf);
         if (err != SASL_OK) {
-            VNC_DEBUG("cannot set SASL external SSF %d (%s)\n",
-                      err, sasl_errstring(err, NULL, NULL));
+            trace_vnc_auth_fail(vs, vs->auth, "cannot set SASL external SSF",
+                                sasl_errstring(err, NULL, NULL));
             sasl_dispose(&vs->sasl.conn);
             vs->sasl.conn = NULL;
             goto authabort;
@@ -617,8 +604,8 @@ void start_auth_sasl(VncState *vs)
 
     err = sasl_setprop(vs->sasl.conn, SASL_SEC_PROPS, &secprops);
     if (err != SASL_OK) {
-        VNC_DEBUG("cannot set SASL security props %d (%s)\n",
-                  err, sasl_errstring(err, NULL, NULL));
+        trace_vnc_auth_fail(vs, vs->auth, "cannot set SASL security props",
+                            sasl_errstring(err, NULL, NULL));
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
@@ -633,13 +620,13 @@ void start_auth_sasl(VncState *vs)
                         NULL,
                         NULL);
     if (err != SASL_OK) {
-        VNC_DEBUG("cannot list SASL mechanisms %d (%s)\n",
-                  err, sasl_errdetail(vs->sasl.conn));
+        trace_vnc_auth_fail(vs, vs->auth, "cannot list SASL mechanisms",
+                            sasl_errdetail(vs->sasl.conn));
         sasl_dispose(&vs->sasl.conn);
         vs->sasl.conn = NULL;
         goto authabort;
     }
-    VNC_DEBUG("Available mechanisms for client: '%s'\n", mechlist);
+    trace_vnc_auth_sasl_mech_list(vs, mechlist);
 
     vs->sasl.mechlist = g_strdup(mechlist);
     mechlistlen = strlen(mechlist);
@@ -647,12 +634,12 @@ void start_auth_sasl(VncState *vs)
     vnc_write(vs, mechlist, mechlistlen);
     vnc_flush(vs);
 
-    VNC_DEBUG("Wait for client mechname length\n");
     vnc_read_when(vs, protocol_client_auth_sasl_mechname_len, 4);
 
     return;
 
  authabort:
+    error_free(local_err);
     vnc_client_error(vs);
 }
 

ui/vnc-auth-vencrypt.c

@@ -35,27 +35,24 @@ static void start_auth_vencrypt_subauth(VncState *vs)
     switch (vs->subauth) {
     case VNC_AUTH_VENCRYPT_TLSNONE:
     case VNC_AUTH_VENCRYPT_X509NONE:
-       VNC_DEBUG("Accept TLS auth none\n");
        vnc_write_u32(vs, 0); /* Accept auth completion */
        start_client_init(vs);
        break;
 
     case VNC_AUTH_VENCRYPT_TLSVNC:
     case VNC_AUTH_VENCRYPT_X509VNC:
-       VNC_DEBUG("Start TLS auth VNC\n");
        start_auth_vnc(vs);
        break;
 
 #ifdef CONFIG_VNC_SASL
     case VNC_AUTH_VENCRYPT_TLSSASL:
     case VNC_AUTH_VENCRYPT_X509SASL:
-      VNC_DEBUG("Start TLS auth SASL\n");
       start_auth_sasl(vs);
       break;
 #endif /* CONFIG_VNC_SASL */
 
     default: /* Should not be possible, but just in case */
-       VNC_DEBUG("Reject subauth %d server bug\n", vs->auth);
+       trace_vnc_auth_fail(vs, vs->auth, "Unhandled VeNCrypt subauth", "");
        vnc_write_u8(vs, 1);
        if (vs->minor >= 8) {
            static const char err[] = "Unsupported authentication type";
@@ -73,8 +70,8 @@ static void vnc_tls_handshake_done(QIOTask *task,
     Error *err = NULL;
 
     if (qio_task_propagate_error(task, &err)) {
-        VNC_DEBUG("Handshake failed %s\n",
-                  error_get_pretty(err));
+        trace_vnc_auth_fail(vs, vs->auth, "TLS handshake failed",
+                            error_get_pretty(err));
         vnc_client_error(vs);
         error_free(err);
     } else {
@@ -89,15 +86,15 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len
 {
     int auth = read_u32(data, 0);
 
+    trace_vnc_auth_vencrypt_subauth(vs, auth);
     if (auth != vs->subauth) {
-        VNC_DEBUG("Rejecting auth %d\n", auth);
+        trace_vnc_auth_fail(vs, vs->auth, "Unsupported sub-auth version", "");
         vnc_write_u8(vs, 0); /* Reject auth */
         vnc_flush(vs);
         vnc_client_error(vs);
     } else {
         Error *err = NULL;
         QIOChannelTLS *tls;
-        VNC_DEBUG("Accepting auth %d, setting up TLS for handshake\n", auth);
         vnc_write_u8(vs, 1); /* Accept auth */
         vnc_flush(vs);
 
@@ -112,14 +109,14 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len
             vs->vd->tlsaclname,
             &err);
         if (!tls) {
-            VNC_DEBUG("Failed to setup TLS %s\n", error_get_pretty(err));
+            trace_vnc_auth_fail(vs, vs->auth, "TLS setup failed",
+                                error_get_pretty(err));
             error_free(err);
             vnc_client_error(vs);
             return 0;
         }
 
         qio_channel_set_name(QIO_CHANNEL(tls), "vnc-server-tls");
-        VNC_DEBUG("Start TLS VeNCrypt handshake process\n");
         object_unref(OBJECT(vs->ioc));
         vs->ioc = QIO_CHANNEL(tls);
         trace_vnc_client_io_wrap(vs, vs->ioc, "tls");
@@ -135,14 +132,14 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len
 
 static int protocol_client_vencrypt_init(VncState *vs, uint8_t *data, size_t len)
 {
+    trace_vnc_auth_vencrypt_version(vs, (int)data[0], (int)data[1]);
     if (data[0] != 0 ||
         data[1] != 2) {
-        VNC_DEBUG("Unsupported VeNCrypt protocol %d.%d\n", (int)data[0], (int)data[1]);
+        trace_vnc_auth_fail(vs, vs->auth, "Unsupported version", "");
         vnc_write_u8(vs, 1); /* Reject version */
         vnc_flush(vs);
         vnc_client_error(vs);
     } else {
-        VNC_DEBUG("Sending allowed auth %d\n", vs->subauth);
         vnc_write_u8(vs, 0); /* Accept version */
         vnc_write_u8(vs, 1); /* Number of sub-auths */
         vnc_write_u32(vs, vs->subauth); /* The supported auth */

ui/vnc.c

@@ -2406,11 +2406,11 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)
     Error *err = NULL;
 
     if (!vs->vd->password) {
-        VNC_DEBUG("No password configured on server");
+        trace_vnc_auth_fail(vs, vs->auth, "password is not set", "");
         goto reject;
     }
     if (vs->vd->expires < now) {
-        VNC_DEBUG("Password is expired");
+        trace_vnc_auth_fail(vs, vs->auth, "password is expired", "");
         goto reject;
     }
 
@@ -2427,8 +2427,8 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)
         key, G_N_ELEMENTS(key),
         &err);
     if (!cipher) {
-        VNC_DEBUG("Cannot initialize cipher %s",
-                  error_get_pretty(err));
+        trace_vnc_auth_fail(vs, vs->auth, "cannot create cipher",
+                            error_get_pretty(err));
         error_free(err);
         goto reject;
     }
@@ -2438,18 +2438,18 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)
                                response,
                                VNC_AUTH_CHALLENGE_SIZE,
                                &err) < 0) {
-        VNC_DEBUG("Cannot encrypt challenge %s",
-                  error_get_pretty(err));
+        trace_vnc_auth_fail(vs, vs->auth, "cannot encrypt challenge response",
+                            error_get_pretty(err));
         error_free(err);
         goto reject;
     }
 
     /* Compare expected vs actual challenge response */
     if (memcmp(response, data, VNC_AUTH_CHALLENGE_SIZE) != 0) {
-        VNC_DEBUG("Client challenge response did not match\n");
+        trace_vnc_auth_fail(vs, vs->auth, "mis-matched challenge response", "");
         goto reject;
     } else {
-        VNC_DEBUG("Accepting VNC challenge response\n");
+        trace_vnc_auth_pass(vs, vs->auth);
         vnc_write_u32(vs, 0); /* Accept auth */
         vnc_flush(vs);
 
@@ -2488,7 +2488,7 @@ static int protocol_client_auth(VncState *vs, uint8_t *data, size_t len)
     /* We only advertise 1 auth scheme at a time, so client
      * must pick the one we sent. Verify this */
     if (data[0] != vs->auth) { /* Reject auth */
-       VNC_DEBUG("Reject auth %d because it didn't match advertized\n", (int)data[0]);
+       trace_vnc_auth_reject(vs, vs->auth, (int)data[0]);
        vnc_write_u32(vs, 1);
        if (vs->minor >= 8) {
            static const char err[] = "Authentication failed";
@@ -2497,36 +2497,33 @@ static int protocol_client_auth(VncState *vs, uint8_t *data, size_t len)
        }
        vnc_client_error(vs);
     } else { /* Accept requested auth */
-       VNC_DEBUG("Client requested auth %d\n", (int)data[0]);
+       trace_vnc_auth_start(vs, vs->auth);
        switch (vs->auth) {
        case VNC_AUTH_NONE:
-           VNC_DEBUG("Accept auth none\n");
            if (vs->minor >= 8) {
                vnc_write_u32(vs, 0); /* Accept auth completion */
                vnc_flush(vs);
            }
+           trace_vnc_auth_pass(vs, vs->auth);
            start_client_init(vs);
            break;
 
        case VNC_AUTH_VNC:
-           VNC_DEBUG("Start VNC auth\n");
            start_auth_vnc(vs);
            break;
 
        case VNC_AUTH_VENCRYPT:
-           VNC_DEBUG("Accept VeNCrypt auth\n");
            start_auth_vencrypt(vs);
            break;
 
 #ifdef CONFIG_VNC_SASL
        case VNC_AUTH_SASL:
-           VNC_DEBUG("Accept SASL auth\n");
            start_auth_sasl(vs);
            break;
 #endif /* CONFIG_VNC_SASL */
 
        default: /* Should not be possible, but just in case */
-           VNC_DEBUG("Reject auth %d server code bug\n", vs->auth);
+           trace_vnc_auth_fail(vs, vs->auth, "Unhandled auth method", "");
            vnc_write_u8(vs, 1);
            if (vs->minor >= 8) {
                static const char err[] = "Authentication failed";
@@ -2571,10 +2568,11 @@ static int protocol_version(VncState *vs, uint8_t *version, size_t len)
         vs->minor = 3;
 
     if (vs->minor == 3) {
+        trace_vnc_auth_start(vs, vs->auth);
         if (vs->auth == VNC_AUTH_NONE) {
-            VNC_DEBUG("Tell client auth none\n");
             vnc_write_u32(vs, vs->auth);
             vnc_flush(vs);
+            trace_vnc_auth_pass(vs, vs->auth);
             start_client_init(vs);
        } else if (vs->auth == VNC_AUTH_VNC) {
             VNC_DEBUG("Tell client VNC auth\n");
@@ -2582,13 +2580,13 @@ static int protocol_version(VncState *vs, uint8_t *version, size_t len)
             vnc_flush(vs);
             start_auth_vnc(vs);
        } else {
-            VNC_DEBUG("Unsupported auth %d for protocol 3.3\n", vs->auth);
+            trace_vnc_auth_fail(vs, vs->auth,
+                                "Unsupported auth method for v3.3", "");
             vnc_write_u32(vs, VNC_AUTH_INVALID);
             vnc_flush(vs);
             vnc_client_error(vs);
        }
     } else {
-        VNC_DEBUG("Telling client we support auth %d\n", vs->auth);
         vnc_write_u8(vs, 1); /* num auth */
         vnc_write_u8(vs, vs->auth);
         vnc_read_when(vs, protocol_client_auth, 1);
@@ -3942,12 +3940,14 @@ void vnc_display_open(const char *id, Error **errp)
                                sasl, false, errp) < 0) {
         goto fail;
     }
+    trace_vnc_auth_init(vd, 0, vd->auth, vd->subauth);
 
     if (vnc_display_setup_auth(&vd->ws_auth, &vd->ws_subauth,
                                vd->tlscreds, password,
                                sasl, true, errp) < 0) {
         goto fail;
     }
+    trace_vnc_auth_init(vd, 1, vd->ws_auth, vd->ws_subauth);
 
 #ifdef CONFIG_VNC_SASL
     if ((saslErr = sasl_server_init(NULL, "qemu")) != SASL_OK) {