{"id":816835,"url":"http://patchwork.ozlabs.org/api/patches/816835/?format=json","web_url":"http://patchwork.ozlabs.org/project/qemu-devel/patch/20170921121528.23935-3-berrange@redhat.com/","project":{"id":14,"url":"http://patchwork.ozlabs.org/api/projects/14/?format=json","name":"QEMU Development","link_name":"qemu-devel","list_id":"qemu-devel.nongnu.org","list_email":"qemu-devel@nongnu.org","web_url":"","scm_url":"","webscm_url":"","list_archive_url":"","list_archive_url_format":"","commit_url_format":""},"msgid":"<20170921121528.23935-3-berrange@redhat.com>","list_archive_url":null,"date":"2017-09-21T12:15:28","name":"[2/2] ui: add tracing of VNC authentication process","commit_ref":null,"pull_url":null,"state":"new","archived":false,"hash":"a74454e4ba56c7e7c3330607c728affffc029649","submitter":{"id":2694,"url":"http://patchwork.ozlabs.org/api/people/2694/?format=json","name":"Daniel P. Berrangé","email":"berrange@redhat.com"},"delegate":null,"mbox":"http://patchwork.ozlabs.org/project/qemu-devel/patch/20170921121528.23935-3-berrange@redhat.com/mbox/","series":[{"id":4367,"url":"http://patchwork.ozlabs.org/api/series/4367/?format=json","web_url":"http://patchwork.ozlabs.org/project/qemu-devel/list/?series=4367","date":"2017-09-21T12:15:26","name":"Add more trace points to VNC code","version":1,"mbox":"http://patchwork.ozlabs.org/series/4367/mbox/"}],"comments":"http://patchwork.ozlabs.org/api/patches/816835/comments/","check":"pending","checks":"http://patchwork.ozlabs.org/api/patches/816835/checks/","tags":{},"related":[],"headers":{"Return-Path":"","X-Original-To":"incoming@patchwork.ozlabs.org","Delivered-To":"patchwork-incoming@bilbo.ozlabs.org","Authentication-Results":["ozlabs.org;\n\tspf=pass (mailfrom) smtp.mailfrom=nongnu.org\n\t(client-ip=2001:4830:134:3::11; helo=lists.gnu.org;\n\tenvelope-from=qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org;\n\treceiver=)","ext-mx02.extmail.prod.ext.phx2.redhat.com;\n\tdmarc=none (p=none dis=none) header.from=redhat.com","ext-mx02.extmail.prod.ext.phx2.redhat.com;\n\tspf=fail smtp.mailfrom=berrange@redhat.com"],"Received":["from lists.gnu.org (lists.gnu.org [IPv6:2001:4830:134:3::11])\n\t(using TLSv1 with cipher AES256-SHA (256/256 bits))\n\t(No client certificate requested)\n\tby ozlabs.org (Postfix) with ESMTPS id 3xybGj2Sw1z9s5L\n\tfor ;\n\tThu, 21 Sep 2017 22:17:49 +1000 (AEST)","from localhost ([::1]:53414 helo=lists.gnu.org)\n\tby lists.gnu.org with esmtp (Exim 4.71) (envelope-from\n\t)\n\tid 1dv0QN-0007oh-FT\n\tfor incoming@patchwork.ozlabs.org; Thu, 21 Sep 2017 08:17:47 -0400","from eggs.gnu.org ([2001:4830:134:3::10]:41187)\n\tby lists.gnu.org with esmtp (Exim 4.71)\n\t(envelope-from ) id 1dv0OL-0006Zw-7L\n\tfor qemu-devel@nongnu.org; Thu, 21 Sep 2017 08:15:44 -0400","from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71)\n\t(envelope-from ) id 1dv0OI-0008Dq-G0\n\tfor qemu-devel@nongnu.org; Thu, 21 Sep 2017 08:15:41 -0400","from mx1.redhat.com ([209.132.183.28]:46620)\n\tby eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32)\n\t(Exim 4.71) (envelope-from ) id 1dv0OH-0008CM-O8\n\tfor qemu-devel@nongnu.org; Thu, 21 Sep 2017 08:15:38 -0400","from smtp.corp.redhat.com\n\t(int-mx04.intmail.prod.int.phx2.redhat.com [10.5.11.14])\n\t(using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits))\n\t(No client certificate requested)\n\tby mx1.redhat.com (Postfix) with ESMTPS id D7ED7806B2\n\tfor ; Thu, 21 Sep 2017 12:15:36 +0000 (UTC)","from t460.redhat.com (unknown [10.33.36.54])\n\tby smtp.corp.redhat.com (Postfix) with ESMTP id 971585D97C;\n\tThu, 21 Sep 2017 12:15:35 +0000 (UTC)"],"DMARC-Filter":"OpenDMARC Filter v1.3.2 mx1.redhat.com D7ED7806B2","From":"\"Daniel P. Berrange\" ","To":"qemu-devel@nongnu.org","Date":"Thu, 21 Sep 2017 13:15:28 +0100","Message-Id":"<20170921121528.23935-3-berrange@redhat.com>","In-Reply-To":"<20170921121528.23935-1-berrange@redhat.com>","References":"<20170921121528.23935-1-berrange@redhat.com>","X-Scanned-By":"MIMEDefang 2.79 on 10.5.11.14","X-Greylist":"Sender IP whitelisted, not delayed by milter-greylist-4.5.16\n\t(mx1.redhat.com [10.5.110.26]);\n\tThu, 21 Sep 2017 12:15:37 +0000 (UTC)","X-detected-operating-system":"by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic]\n\t[fuzzy]","X-Received-From":"209.132.183.28","Subject":"[Qemu-devel] [PATCH 2/2] ui: add tracing of VNC authentication\n\tprocess","X-BeenThere":"qemu-devel@nongnu.org","X-Mailman-Version":"2.1.21","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"Gerd Hoffmann ","Errors-To":"qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org","Sender":"\"Qemu-devel\"\n\t"},"content":"Trace anything related to authentication in the VNC protocol\nhandshake\n\nSigned-off-by: Daniel P. Berrange \n---\n ui/trace-events | 15 +++++++\n ui/vnc-auth-sasl.c | 113 ++++++++++++++++++++++---------------------------\n ui/vnc-auth-vencrypt.c | 21 ++++-----\n ui/vnc.c | 36 ++++++++--------\n 4 files changed, 92 insertions(+), 93 deletions(-)","diff":"diff --git a/ui/trace-events b/ui/trace-events\nindex e4c02e47f5..1a9f126330 100644\n--- a/ui/trace-events\n+++ b/ui/trace-events\n@@ -35,6 +35,21 @@ vnc_client_connect(void *state, void *ioc) \"VNC client connect state=%p ioc=%p\"\n vnc_client_disconnect_start(void *state, void *ioc) \"VNC client disconnect start state=%p ioc=%p\"\n vnc_client_disconnect_finish(void *state, void *ioc) \"VNC client disconnect finish state=%p ioc=%p\"\n vnc_client_io_wrap(void *state, void *ioc, const char *type) \"VNC client I/O wrap state=%p ioc=%p type=%s\"\n+vnc_auth_init(void *display, int websock, int auth, int subauth) \"VNC auth init state=%p websock=%d auth=%d subauth=%d\"\n+vnc_auth_start(void *state, int method) \"VNC client auth start state=%p method=%d\"\n+vnc_auth_pass(void *state, int method) \"VNC client auth passed state=%p method=%d\"\n+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\"\n+vnc_auth_reject(void *state, int expect, int got) \"VNC client auth rejected state=%p method expected=%d got=%d\"\n+vnc_auth_vencrypt_version(void *state, int major, int minor) \"VNC client auth vencrypt version state=%p major=%d minor=%d\"\n+vnc_auth_vencrypt_subauth(void *state, int auth) \"VNC client auth vencrypt subauth state=%p auth=%d\"\n+vnc_auth_sasl_mech_list(void *state, const char *mechs) \"VNC client auth SASL state=%p mechlist=%s\"\n+vnc_auth_sasl_mech_choose(void *state, const char *mech) \"VNC client auth SASL state=%p mech=%s\"\n+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\"\n+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\"\n+vnc_auth_sasl_ssf(void *state, int ssf) \"VNC client auth SASL SSF state=%p size=%d\"\n+vnc_auth_sasl_username(void *state, const char *name) \"VNC client auth SASL user state=%p name=%s\"\n+vnc_auth_sasl_acl(void *state, int allow) \"VNC client auth SASL ACL state=%p allow=%d\"\n+\n \n # ui/input.c\n input_event_key_number(int conidx, int number, const char *qcode, bool down) \"con %d, key number 0x%x [%s], down %d\"\ndiff --git a/ui/vnc-auth-sasl.c b/ui/vnc-auth-sasl.c\nindex 3ade4a4918..23f28280e7 100644\n--- a/ui/vnc-auth-sasl.c\n+++ b/ui/vnc-auth-sasl.c\n@@ -25,6 +25,7 @@\n #include \"qemu/osdep.h\"\n #include \"qapi/error.h\"\n #include \"vnc.h\"\n+#include \"trace.h\"\n \n /* Max amount of data we send/recv for SASL steps to prevent DOS */\n #define SASL_DATA_MAX_LEN (1024 * 1024)\n@@ -133,27 +134,26 @@ static int vnc_auth_sasl_check_access(VncState *vs)\n \n err = sasl_getprop(vs->sasl.conn, SASL_USERNAME, &val);\n if (err != SASL_OK) {\n- VNC_DEBUG(\"cannot query SASL username on connection %d (%s), denying access\\n\",\n- err, sasl_errstring(err, NULL, NULL));\n+ trace_vnc_auth_fail(vs, vs->auth, \"Cannot fetch SASL username\",\n+ sasl_errstring(err, NULL, NULL));\n return -1;\n }\n if (val == NULL) {\n- VNC_DEBUG(\"no client username was found, denying access\\n\");\n+ trace_vnc_auth_fail(vs, vs->auth, \"No SASL username set\", \"\");\n return -1;\n }\n- VNC_DEBUG(\"SASL client username %s\\n\", (const char *)val);\n \n vs->sasl.username = g_strdup((const char*)val);\n+ trace_vnc_auth_sasl_username(vs, vs->sasl.username);\n \n if (vs->vd->sasl.acl == NULL) {\n- VNC_DEBUG(\"no ACL activated, allowing access\\n\");\n+ trace_vnc_auth_sasl_acl(vs, 1);\n return 0;\n }\n \n allow = qemu_acl_party_is_allowed(vs->vd->sasl.acl, vs->sasl.username);\n \n- VNC_DEBUG(\"SASL client %s %s by ACL\\n\", vs->sasl.username,\n- allow ? \"allowed\" : \"denied\");\n+ trace_vnc_auth_sasl_acl(vs, allow);\n return allow ? 0 : -1;\n }\n \n@@ -170,7 +170,9 @@ static int vnc_auth_sasl_check_ssf(VncState *vs)\n return 0;\n \n ssf = *(const int *)val;\n- VNC_DEBUG(\"negotiated an SSF of %d\\n\", ssf);\n+\n+ trace_vnc_auth_sasl_ssf(vs, ssf);\n+\n if (ssf < 56)\n return 0; /* 56 is good for Kerberos */\n \n@@ -218,33 +220,28 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le\n datalen--; /* Don't count NULL byte when passing to _start() */\n }\n \n- VNC_DEBUG(\"Step using SASL Data %p (%d bytes)\\n\",\n- clientdata, datalen);\n err = sasl_server_step(vs->sasl.conn,\n clientdata,\n datalen,\n &serverout,\n &serveroutlen);\n+ trace_vnc_auth_sasl_step(vs, data, len, serverout, serveroutlen, err);\n if (err != SASL_OK &&\n err != SASL_CONTINUE) {\n- VNC_DEBUG(\"sasl step failed %d (%s)\\n\",\n- err, sasl_errdetail(vs->sasl.conn));\n+ trace_vnc_auth_fail(vs, vs->auth, \"Cannot step SASL auth\",\n+ sasl_errdetail(vs->sasl.conn));\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n }\n \n if (serveroutlen > SASL_DATA_MAX_LEN) {\n- VNC_DEBUG(\"sasl step reply data too long %d\\n\",\n- serveroutlen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL data too long\", \"\");\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n }\n \n- VNC_DEBUG(\"SASL return data %d bytes, nil; %d\\n\",\n- serveroutlen, serverout ? 0 : 1);\n-\n if (serveroutlen) {\n vnc_write_u32(vs, serveroutlen + 1);\n vnc_write(vs, serverout, serveroutlen + 1);\n@@ -256,22 +253,20 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le\n vnc_write_u8(vs, err == SASL_CONTINUE ? 0 : 1);\n \n if (err == SASL_CONTINUE) {\n- VNC_DEBUG(\"%s\", \"Authentication must continue\\n\");\n /* Wait for step length */\n vnc_read_when(vs, protocol_client_auth_sasl_step_len, 4);\n } else {\n if (!vnc_auth_sasl_check_ssf(vs)) {\n- VNC_DEBUG(\"Authentication rejected for weak SSF %p\\n\", vs->ioc);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL SSF too weak\", \"\");\n goto authreject;\n }\n \n /* Check username whitelist ACL */\n if (vnc_auth_sasl_check_access(vs) < 0) {\n- VNC_DEBUG(\"Authentication rejected for ACL %p\\n\", vs->ioc);\n goto authreject;\n }\n \n- VNC_DEBUG(\"Authentication successful %p\\n\", vs->ioc);\n+ trace_vnc_auth_pass(vs, vs->auth);\n vnc_write_u32(vs, 0); /* Accept auth */\n /*\n * Delay writing in SSF encoded mode until pending output\n@@ -300,9 +295,9 @@ static int protocol_client_auth_sasl_step(VncState *vs, uint8_t *data, size_t le\n static int protocol_client_auth_sasl_step_len(VncState *vs, uint8_t *data, size_t len)\n {\n uint32_t steplen = read_u32(data, 0);\n- VNC_DEBUG(\"Got client step len %d\\n\", steplen);\n+\n if (steplen > SASL_DATA_MAX_LEN) {\n- VNC_DEBUG(\"Too much SASL data %d\\n\", steplen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL step len too large\", \"\");\n vnc_client_error(vs);\n return -1;\n }\n@@ -346,33 +341,28 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l\n datalen--; /* Don't count NULL byte when passing to _start() */\n }\n \n- VNC_DEBUG(\"Start SASL auth with mechanism %s. Data %p (%d bytes)\\n\",\n- vs->sasl.mechlist, clientdata, datalen);\n err = sasl_server_start(vs->sasl.conn,\n vs->sasl.mechlist,\n clientdata,\n datalen,\n &serverout,\n &serveroutlen);\n+ trace_vnc_auth_sasl_start(vs, data, len, serverout, serveroutlen, err);\n if (err != SASL_OK &&\n err != SASL_CONTINUE) {\n- VNC_DEBUG(\"sasl start failed %d (%s)\\n\",\n- err, sasl_errdetail(vs->sasl.conn));\n+ trace_vnc_auth_fail(vs, vs->auth, \"Cannot start SASL auth\",\n+ sasl_errdetail(vs->sasl.conn));\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n }\n if (serveroutlen > SASL_DATA_MAX_LEN) {\n- VNC_DEBUG(\"sasl start reply data too long %d\\n\",\n- serveroutlen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL data too long\", \"\");\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n }\n \n- VNC_DEBUG(\"SASL return data %d bytes, nil; %d\\n\",\n- serveroutlen, serverout ? 0 : 1);\n-\n if (serveroutlen) {\n vnc_write_u32(vs, serveroutlen + 1);\n vnc_write(vs, serverout, serveroutlen + 1);\n@@ -384,22 +374,20 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l\n vnc_write_u8(vs, err == SASL_CONTINUE ? 0 : 1);\n \n if (err == SASL_CONTINUE) {\n- VNC_DEBUG(\"%s\", \"Authentication must continue\\n\");\n /* Wait for step length */\n vnc_read_when(vs, protocol_client_auth_sasl_step_len, 4);\n } else {\n if (!vnc_auth_sasl_check_ssf(vs)) {\n- VNC_DEBUG(\"Authentication rejected for weak SSF %p\\n\", vs->ioc);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL SSF too weak\", \"\");\n goto authreject;\n }\n \n /* Check username whitelist ACL */\n if (vnc_auth_sasl_check_access(vs) < 0) {\n- VNC_DEBUG(\"Authentication rejected for ACL %p\\n\", vs->ioc);\n goto authreject;\n }\n \n- VNC_DEBUG(\"Authentication successful %p\\n\", vs->ioc);\n+ trace_vnc_auth_pass(vs, vs->auth);\n vnc_write_u32(vs, 0); /* Accept auth */\n start_client_init(vs);\n }\n@@ -422,9 +410,9 @@ static int protocol_client_auth_sasl_start(VncState *vs, uint8_t *data, size_t l\n static int protocol_client_auth_sasl_start_len(VncState *vs, uint8_t *data, size_t len)\n {\n uint32_t startlen = read_u32(data, 0);\n- VNC_DEBUG(\"Got client start len %d\\n\", startlen);\n+\n if (startlen > SASL_DATA_MAX_LEN) {\n- VNC_DEBUG(\"Too much SASL data %d\\n\", startlen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL start len too large\", \"\");\n vnc_client_error(vs);\n return -1;\n }\n@@ -439,22 +427,18 @@ static int protocol_client_auth_sasl_start_len(VncState *vs, uint8_t *data, size\n static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_t len)\n {\n char *mechname = g_strndup((const char *) data, len);\n- VNC_DEBUG(\"Got client mechname '%s' check against '%s'\\n\",\n- mechname, vs->sasl.mechlist);\n+ trace_vnc_auth_sasl_mech_choose(vs, mechname);\n \n if (strncmp(vs->sasl.mechlist, mechname, len) == 0) {\n if (vs->sasl.mechlist[len] != '\\0' &&\n vs->sasl.mechlist[len] != ',') {\n- VNC_DEBUG(\"One %d\", vs->sasl.mechlist[len]);\n goto fail;\n }\n } else {\n char *offset = strstr(vs->sasl.mechlist, mechname);\n- VNC_DEBUG(\"Two %p\\n\", offset);\n if (!offset) {\n goto fail;\n }\n- VNC_DEBUG(\"Two '%s'\\n\", offset);\n if (offset[-1] != ',' ||\n (offset[len] != '\\0'&&\n offset[len] != ',')) {\n@@ -465,11 +449,11 @@ static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_\n g_free(vs->sasl.mechlist);\n vs->sasl.mechlist = mechname;\n \n- VNC_DEBUG(\"Validated mechname '%s'\\n\", mechname);\n vnc_read_when(vs, protocol_client_auth_sasl_start_len, 4);\n return 0;\n \n fail:\n+ trace_vnc_auth_fail(vs, vs->auth, \"Unsupported mechname\", mechname);\n vnc_client_error(vs);\n g_free(mechname);\n return -1;\n@@ -478,14 +462,14 @@ static int protocol_client_auth_sasl_mechname(VncState *vs, uint8_t *data, size_\n static int protocol_client_auth_sasl_mechname_len(VncState *vs, uint8_t *data, size_t len)\n {\n uint32_t mechlen = read_u32(data, 0);\n- VNC_DEBUG(\"Got client mechname len %d\\n\", mechlen);\n+\n if (mechlen > 100) {\n- VNC_DEBUG(\"Too long SASL mechname data %d\\n\", mechlen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL mechname too long\", \"\");\n vnc_client_error(vs);\n return -1;\n }\n if (mechlen < 1) {\n- VNC_DEBUG(\"Too short SASL mechname %d\\n\", mechlen);\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL mechname too short\", \"\");\n vnc_client_error(vs);\n return -1;\n }\n@@ -524,19 +508,22 @@ void start_auth_sasl(VncState *vs)\n const char *mechlist = NULL;\n sasl_security_properties_t secprops;\n int err;\n+ Error *local_err = NULL;\n char *localAddr, *remoteAddr;\n int mechlistlen;\n \n- VNC_DEBUG(\"Initialize SASL auth %p\\n\", vs->ioc);\n-\n /* Get local & remote client addresses in form IPADDR;PORT */\n- localAddr = vnc_socket_ip_addr_string(vs->sioc, true, NULL);\n+ localAddr = vnc_socket_ip_addr_string(vs->sioc, true, &local_err);\n if (!localAddr) {\n+ trace_vnc_auth_fail(vs, vs->auth, \"Cannot format local IP\",\n+ error_get_pretty(local_err));\n goto authabort;\n }\n \n- remoteAddr = vnc_socket_ip_addr_string(vs->sioc, false, NULL);\n+ remoteAddr = vnc_socket_ip_addr_string(vs->sioc, false, &local_err);\n if (!remoteAddr) {\n+ trace_vnc_auth_fail(vs, vs->auth, \"Cannot format remote IP\",\n+ error_get_pretty(local_err));\n g_free(localAddr);\n goto authabort;\n }\n@@ -554,8 +541,8 @@ void start_auth_sasl(VncState *vs)\n localAddr = remoteAddr = NULL;\n \n if (err != SASL_OK) {\n- VNC_DEBUG(\"sasl context setup failed %d (%s)\",\n- err, sasl_errstring(err, NULL, NULL));\n+ trace_vnc_auth_fail(vs, vs->auth, \"SASL context setup failed\",\n+ sasl_errstring(err, NULL, NULL));\n vs->sasl.conn = NULL;\n goto authabort;\n }\n@@ -570,8 +557,8 @@ void start_auth_sasl(VncState *vs)\n keysize = qcrypto_tls_session_get_key_size(vs->tls,\n &local_err);\n if (keysize < 0) {\n- VNC_DEBUG(\"cannot TLS get cipher size: %s\\n\",\n- error_get_pretty(local_err));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot TLS get cipher size\",\n+ error_get_pretty(local_err));\n error_free(local_err);\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n@@ -581,8 +568,8 @@ void start_auth_sasl(VncState *vs)\n \n err = sasl_setprop(vs->sasl.conn, SASL_SSF_EXTERNAL, &ssf);\n if (err != SASL_OK) {\n- VNC_DEBUG(\"cannot set SASL external SSF %d (%s)\\n\",\n- err, sasl_errstring(err, NULL, NULL));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot set SASL external SSF\",\n+ sasl_errstring(err, NULL, NULL));\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n@@ -617,8 +604,8 @@ void start_auth_sasl(VncState *vs)\n \n err = sasl_setprop(vs->sasl.conn, SASL_SEC_PROPS, &secprops);\n if (err != SASL_OK) {\n- VNC_DEBUG(\"cannot set SASL security props %d (%s)\\n\",\n- err, sasl_errstring(err, NULL, NULL));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot set SASL security props\",\n+ sasl_errstring(err, NULL, NULL));\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n@@ -633,13 +620,13 @@ void start_auth_sasl(VncState *vs)\n NULL,\n NULL);\n if (err != SASL_OK) {\n- VNC_DEBUG(\"cannot list SASL mechanisms %d (%s)\\n\",\n- err, sasl_errdetail(vs->sasl.conn));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot list SASL mechanisms\",\n+ sasl_errdetail(vs->sasl.conn));\n sasl_dispose(&vs->sasl.conn);\n vs->sasl.conn = NULL;\n goto authabort;\n }\n- VNC_DEBUG(\"Available mechanisms for client: '%s'\\n\", mechlist);\n+ trace_vnc_auth_sasl_mech_list(vs, mechlist);\n \n vs->sasl.mechlist = g_strdup(mechlist);\n mechlistlen = strlen(mechlist);\n@@ -647,12 +634,12 @@ void start_auth_sasl(VncState *vs)\n vnc_write(vs, mechlist, mechlistlen);\n vnc_flush(vs);\n \n- VNC_DEBUG(\"Wait for client mechname length\\n\");\n vnc_read_when(vs, protocol_client_auth_sasl_mechname_len, 4);\n \n return;\n \n authabort:\n+ error_free(local_err);\n vnc_client_error(vs);\n }\n \ndiff --git a/ui/vnc-auth-vencrypt.c b/ui/vnc-auth-vencrypt.c\nindex 2a3766aa64..7833631275 100644\n--- a/ui/vnc-auth-vencrypt.c\n+++ b/ui/vnc-auth-vencrypt.c\n@@ -35,27 +35,24 @@ static void start_auth_vencrypt_subauth(VncState *vs)\n switch (vs->subauth) {\n case VNC_AUTH_VENCRYPT_TLSNONE:\n case VNC_AUTH_VENCRYPT_X509NONE:\n- VNC_DEBUG(\"Accept TLS auth none\\n\");\n vnc_write_u32(vs, 0); /* Accept auth completion */\n start_client_init(vs);\n break;\n \n case VNC_AUTH_VENCRYPT_TLSVNC:\n case VNC_AUTH_VENCRYPT_X509VNC:\n- VNC_DEBUG(\"Start TLS auth VNC\\n\");\n start_auth_vnc(vs);\n break;\n \n #ifdef CONFIG_VNC_SASL\n case VNC_AUTH_VENCRYPT_TLSSASL:\n case VNC_AUTH_VENCRYPT_X509SASL:\n- VNC_DEBUG(\"Start TLS auth SASL\\n\");\n start_auth_sasl(vs);\n break;\n #endif /* CONFIG_VNC_SASL */\n \n default: /* Should not be possible, but just in case */\n- VNC_DEBUG(\"Reject subauth %d server bug\\n\", vs->auth);\n+ trace_vnc_auth_fail(vs, vs->auth, \"Unhandled VeNCrypt subauth\", \"\");\n vnc_write_u8(vs, 1);\n if (vs->minor >= 8) {\n static const char err[] = \"Unsupported authentication type\";\n@@ -73,8 +70,8 @@ static void vnc_tls_handshake_done(QIOTask *task,\n Error *err = NULL;\n \n if (qio_task_propagate_error(task, &err)) {\n- VNC_DEBUG(\"Handshake failed %s\\n\",\n- error_get_pretty(err));\n+ trace_vnc_auth_fail(vs, vs->auth, \"TLS handshake failed\",\n+ error_get_pretty(err));\n vnc_client_error(vs);\n error_free(err);\n } else {\n@@ -92,15 +89,15 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len\n {\n int auth = read_u32(data, 0);\n \n+ trace_vnc_auth_vencrypt_subauth(vs, auth);\n if (auth != vs->subauth) {\n- VNC_DEBUG(\"Rejecting auth %d\\n\", auth);\n+ trace_vnc_auth_fail(vs, vs->auth, \"Unsupported sub-auth version\", \"\");\n vnc_write_u8(vs, 0); /* Reject auth */\n vnc_flush(vs);\n vnc_client_error(vs);\n } else {\n Error *err = NULL;\n QIOChannelTLS *tls;\n- VNC_DEBUG(\"Accepting auth %d, setting up TLS for handshake\\n\", auth);\n vnc_write_u8(vs, 1); /* Accept auth */\n vnc_flush(vs);\n \n@@ -115,14 +112,14 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len\n vs->vd->tlsaclname,\n &err);\n if (!tls) {\n- VNC_DEBUG(\"Failed to setup TLS %s\\n\", error_get_pretty(err));\n+ trace_vnc_auth_fail(vs, vs->auth, \"TLS setup failed\",\n+ error_get_pretty(err));\n error_free(err);\n vnc_client_error(vs);\n return 0;\n }\n \n qio_channel_set_name(QIO_CHANNEL(tls), \"vnc-server-tls\");\n- VNC_DEBUG(\"Start TLS VeNCrypt handshake process\\n\");\n object_unref(OBJECT(vs->ioc));\n vs->ioc = QIO_CHANNEL(tls);\n trace_vnc_client_io_wrap(vs, vs->ioc, \"tls\");\n@@ -138,14 +135,14 @@ static int protocol_client_vencrypt_auth(VncState *vs, uint8_t *data, size_t len\n \n static int protocol_client_vencrypt_init(VncState *vs, uint8_t *data, size_t len)\n {\n+ trace_vnc_auth_vencrypt_version(vs, (int)data[0], (int)data[1]);\n if (data[0] != 0 ||\n data[1] != 2) {\n- VNC_DEBUG(\"Unsupported VeNCrypt protocol %d.%d\\n\", (int)data[0], (int)data[1]);\n+ trace_vnc_auth_fail(vs, vs->auth, \"Unsupported version\", \"\");\n vnc_write_u8(vs, 1); /* Reject version */\n vnc_flush(vs);\n vnc_client_error(vs);\n } else {\n- VNC_DEBUG(\"Sending allowed auth %d\\n\", vs->subauth);\n vnc_write_u8(vs, 0); /* Accept version */\n vnc_write_u8(vs, 1); /* Number of sub-auths */\n vnc_write_u32(vs, vs->subauth); /* The supported auth */\ndiff --git a/ui/vnc.c b/ui/vnc.c\nindex 47dacc47b6..9f8d5a1b1f 100644\n--- a/ui/vnc.c\n+++ b/ui/vnc.c\n@@ -2407,11 +2407,11 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)\n Error *err = NULL;\n \n if (!vs->vd->password) {\n- VNC_DEBUG(\"No password configured on server\");\n+ trace_vnc_auth_fail(vs, vs->auth, \"password is not set\", \"\");\n goto reject;\n }\n if (vs->vd->expires < now) {\n- VNC_DEBUG(\"Password is expired\");\n+ trace_vnc_auth_fail(vs, vs->auth, \"password is expired\", \"\");\n goto reject;\n }\n \n@@ -2428,8 +2428,8 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)\n key, G_N_ELEMENTS(key),\n &err);\n if (!cipher) {\n- VNC_DEBUG(\"Cannot initialize cipher %s\",\n- error_get_pretty(err));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot create cipher\",\n+ error_get_pretty(err));\n error_free(err);\n goto reject;\n }\n@@ -2439,18 +2439,18 @@ static int protocol_client_auth_vnc(VncState *vs, uint8_t *data, size_t len)\n response,\n VNC_AUTH_CHALLENGE_SIZE,\n &err) < 0) {\n- VNC_DEBUG(\"Cannot encrypt challenge %s\",\n- error_get_pretty(err));\n+ trace_vnc_auth_fail(vs, vs->auth, \"cannot encrypt challenge response\",\n+ error_get_pretty(err));\n error_free(err);\n goto reject;\n }\n \n /* Compare expected vs actual challenge response */\n if (memcmp(response, data, VNC_AUTH_CHALLENGE_SIZE) != 0) {\n- VNC_DEBUG(\"Client challenge response did not match\\n\");\n+ trace_vnc_auth_fail(vs, vs->auth, \"mis-matched challenge response\", \"\");\n goto reject;\n } else {\n- VNC_DEBUG(\"Accepting VNC challenge response\\n\");\n+ trace_vnc_auth_pass(vs, vs->auth);\n vnc_write_u32(vs, 0); /* Accept auth */\n vnc_flush(vs);\n \n@@ -2489,7 +2489,7 @@ static int protocol_client_auth(VncState *vs, uint8_t *data, size_t len)\n /* We only advertise 1 auth scheme at a time, so client\n * must pick the one we sent. Verify this */\n if (data[0] != vs->auth) { /* Reject auth */\n- VNC_DEBUG(\"Reject auth %d because it didn't match advertized\\n\", (int)data[0]);\n+ trace_vnc_auth_reject(vs, vs->auth, (int)data[0]);\n vnc_write_u32(vs, 1);\n if (vs->minor >= 8) {\n static const char err[] = \"Authentication failed\";\n@@ -2498,36 +2498,33 @@ static int protocol_client_auth(VncState *vs, uint8_t *data, size_t len)\n }\n vnc_client_error(vs);\n } else { /* Accept requested auth */\n- VNC_DEBUG(\"Client requested auth %d\\n\", (int)data[0]);\n+ trace_vnc_auth_start(vs, vs->auth);\n switch (vs->auth) {\n case VNC_AUTH_NONE:\n- VNC_DEBUG(\"Accept auth none\\n\");\n if (vs->minor >= 8) {\n vnc_write_u32(vs, 0); /* Accept auth completion */\n vnc_flush(vs);\n }\n+ trace_vnc_auth_pass(vs, vs->auth);\n start_client_init(vs);\n break;\n \n case VNC_AUTH_VNC:\n- VNC_DEBUG(\"Start VNC auth\\n\");\n start_auth_vnc(vs);\n break;\n \n case VNC_AUTH_VENCRYPT:\n- VNC_DEBUG(\"Accept VeNCrypt auth\\n\");\n start_auth_vencrypt(vs);\n break;\n \n #ifdef CONFIG_VNC_SASL\n case VNC_AUTH_SASL:\n- VNC_DEBUG(\"Accept SASL auth\\n\");\n start_auth_sasl(vs);\n break;\n #endif /* CONFIG_VNC_SASL */\n \n default: /* Should not be possible, but just in case */\n- VNC_DEBUG(\"Reject auth %d server code bug\\n\", vs->auth);\n+ trace_vnc_auth_fail(vs, vs->auth, \"Unhandled auth method\", \"\");\n vnc_write_u8(vs, 1);\n if (vs->minor >= 8) {\n static const char err[] = \"Authentication failed\";\n@@ -2572,10 +2569,11 @@ static int protocol_version(VncState *vs, uint8_t *version, size_t len)\n vs->minor = 3;\n \n if (vs->minor == 3) {\n+ trace_vnc_auth_start(vs, vs->auth);\n if (vs->auth == VNC_AUTH_NONE) {\n- VNC_DEBUG(\"Tell client auth none\\n\");\n vnc_write_u32(vs, vs->auth);\n vnc_flush(vs);\n+ trace_vnc_auth_pass(vs, vs->auth);\n start_client_init(vs);\n } else if (vs->auth == VNC_AUTH_VNC) {\n VNC_DEBUG(\"Tell client VNC auth\\n\");\n@@ -2583,13 +2581,13 @@ static int protocol_version(VncState *vs, uint8_t *version, size_t len)\n vnc_flush(vs);\n start_auth_vnc(vs);\n } else {\n- VNC_DEBUG(\"Unsupported auth %d for protocol 3.3\\n\", vs->auth);\n+ trace_vnc_auth_fail(vs, vs->auth,\n+ \"Unsupported auth method for v3.3\", \"\");\n vnc_write_u32(vs, VNC_AUTH_INVALID);\n vnc_flush(vs);\n vnc_client_error(vs);\n }\n } else {\n- VNC_DEBUG(\"Telling client we support auth %d\\n\", vs->auth);\n vnc_write_u8(vs, 1); /* num auth */\n vnc_write_u8(vs, vs->auth);\n vnc_read_when(vs, protocol_client_auth, 1);\n@@ -3946,12 +3944,14 @@ void vnc_display_open(const char *id, Error **errp)\n sasl, false, errp) < 0) {\n goto fail;\n }\n+ trace_vnc_auth_init(vd, 0, vd->auth, vd->subauth);\n \n if (vnc_display_setup_auth(&vd->ws_auth, &vd->ws_subauth,\n vd->tlscreds, password,\n sasl, true, errp) < 0) {\n goto fail;\n }\n+ trace_vnc_auth_init(vd, 1, vd->ws_auth, vd->ws_subauth);\n \n #ifdef CONFIG_VNC_SASL\n if ((saslErr = sasl_server_init(NULL, \"qemu\")) != SASL_OK) {\n","prefixes":["2/2"]}