ssl-verify: improve logging report in case of errors

Use the log.h system, and report a bit more information in the debug level

1 files changed, 40 insertions, 30 deletions

diff --git a/common/ssl_verify.c b/common/ssl_verify.c
index 236fa01..9ec434d 100644
--- a/common/ssl_verify.c
+++ b/common/ssl_verify.c
@@ -22,6 +22,7 @@
 
 #include "mem.h"
 #include "ssl_verify.h"
+#include "log.h"
 
 #ifndef WIN32
 #include <sys/socket.h>
@@ -31,10 +32,6 @@
 #include <ctype.h>
 #include <string.h>
 
-#ifndef SPICE_DEBUG
-# define SPICE_DEBUG(format, ...)
-#endif
-
 #ifdef WIN32
 static int inet_aton(const char* ip, struct in_addr* in_addr)
 {
@@ -59,36 +56,36 @@ static int verify_pubkey(X509* cert, const char *key, size_t key_size)
         return 0;
 
     if (!cert) {
-        SPICE_DEBUG("warning: no cert!");
+        spice_debug("warning: no cert!");
         return 0;
     }
 
     cert_pubkey = X509_get_pubkey(cert);
     if (!cert_pubkey) {
-        SPICE_DEBUG("warning: reading public key from certificate failed");
+        spice_debug("warning: reading public key from certificate failed");
         goto finish;
     }
 
     bio = BIO_new_mem_buf((void*)key, key_size);
     if (!bio) {
-        SPICE_DEBUG("creating BIO failed");
+        spice_debug("creating BIO failed");
         goto finish;
     }
 
     orig_pubkey = d2i_PUBKEY_bio(bio, NULL);
     if (!orig_pubkey) {
-        SPICE_DEBUG("reading pubkey from bio failed");
+        spice_debug("reading pubkey from bio failed");
         goto finish;
     }
 
     ret = EVP_PKEY_cmp(orig_pubkey, cert_pubkey);
 
     if (ret == 1) {
-        SPICE_DEBUG("public keys match");
+        spice_debug("public keys match");
     } else if (ret == 0) {
-        SPICE_DEBUG("public keys mismatch");
+        spice_debug("public keys mismatch");
     } else {
-        SPICE_DEBUG("public keys types mismatch");
+        spice_debug("public keys types mismatch");
     }
 
 finish:
@@ -170,7 +167,7 @@ static int verify_hostname(X509* cert, const char *hostname)
     X509_NAME* subject;
 
     if (!cert) {
-        SPICE_DEBUG("warning: no cert!");
+        spice_debug("warning: no cert!");
         return 0;
     }
 
@@ -205,7 +202,7 @@ static int verify_hostname(X509* cert, const char *hostname)
                 if (_gnutls_hostname_compare((char *)ASN1_STRING_data(name->d.dNSName),
                                              ASN1_STRING_length(name->d.dNSName),
                                              hostname)) {
-                    SPICE_DEBUG("alt name match=%s", ASN1_STRING_data(name->d.dNSName));
+                    spice_debug("alt name match=%s", ASN1_STRING_data(name->d.dNSName));
                     GENERAL_NAMES_free(subject_alt_names);
                     return 1;
                 }
@@ -214,7 +211,7 @@ static int verify_hostname(X509* cert, const char *hostname)
                 found_dns_name = 1;
                 if ((addr_len == alt_ip_len)&&
                     !memcmp(ASN1_STRING_data(name->d.iPAddress), &addr, addr_len)) {
-                    SPICE_DEBUG("alt name IP match=%s",
+                    spice_debug("alt name IP match=%s",
                                 inet_ntoa(*((struct in_addr*)ASN1_STRING_data(name->d.dNSName))));
                     GENERAL_NAMES_free(subject_alt_names);
                     return 1;
@@ -225,7 +222,7 @@ static int verify_hostname(X509* cert, const char *hostname)
     }
 
     if (found_dns_name) {
-        SPICE_DEBUG("warning: SubjectAltName mismatch");
+        spice_debug("warning: SubjectAltName mismatch");
         return 0;
     }
 
@@ -249,7 +246,7 @@ static int verify_hostname(X509* cert, const char *hostname)
             if (_gnutls_hostname_compare((char*)ASN1_STRING_data(cn_asn1),
                                          ASN1_STRING_length(cn_asn1),
                                          hostname)) {
-                SPICE_DEBUG("common name match=%s", (char*)ASN1_STRING_data(cn_asn1));
+                spice_debug("common name match=%s", (char*)ASN1_STRING_data(cn_asn1));
                 cn_match = 1;
                 break;
             }
@@ -257,7 +254,7 @@ static int verify_hostname(X509* cert, const char *hostname)
     }
 
     if (!cn_match) {
-        SPICE_DEBUG("warning: common name mismatch");
+        spice_debug("warning: common name mismatch");
     }
 
     return cn_match;
@@ -278,7 +275,7 @@ static X509_NAME* subject_to_x509_name(const char *subject, int *nentries)
     in_subject = X509_NAME_new();
 
     if (!in_subject || !key || !val) {
-        SPICE_DEBUG("failed to allocate");
+        spice_debug("failed to allocate");
         return NULL;
     }
 
@@ -291,7 +288,7 @@ static X509_NAME* subject_to_x509_name(const char *subject, int *nentries)
         if (*p == '\\') {
             ++p;
             if (*p != '\\' && *p != ',') {
-                SPICE_DEBUG("Invalid character after \\");
+                spice_debug("Invalid character after \\");
                 goto fail;
             }
             escape = 1;
@@ -325,7 +322,7 @@ static X509_NAME* subject_to_x509_name(const char *subject, int *nentries)
                                                 MBSTRING_UTF8,
                                                 (const unsigned char*)val,
                                                 -1, -1, 0)) {
-                    SPICE_DEBUG("warning: failed to add entry %s=%s to X509_NAME",
+                    spice_debug("warning: failed to add entry %s=%s to X509_NAME",
                                 key, val);
                     goto fail;
                 }
@@ -359,27 +356,27 @@ static int verify_subject(X509* cert, SpiceOpenSSLVerify* verify)
     int in_entries;
 
     if (!cert) {
-        SPICE_DEBUG("warning: no cert!");
+        spice_debug("warning: no cert!");
         return 0;
     }
 
     cert_subject = X509_get_subject_name(cert);
     if (!cert_subject) {
-        SPICE_DEBUG("warning: reading certificate subject failed");
+        spice_debug("warning: reading certificate subject failed");
         return 0;
     }
 
     if (!verify->in_subject) {
         verify->in_subject = subject_to_x509_name(verify->subject, &in_entries);
         if (!verify->in_subject) {
-            SPICE_DEBUG("warning: no in_subject!");
+            spice_debug("warning: no in_subject!");
             return 0;
         }
     }
 
     /* Note: this check is redundant with the pre-condition in X509_NAME_cmp */
     if (X509_NAME_entry_count(cert_subject) != in_entries) {
-        SPICE_DEBUG("subject mismatch: #entries cert=%d, input=%d",
+        spice_debug("subject mismatch: #entries cert=%d, input=%d",
             X509_NAME_entry_count(cert_subject), in_entries);
         return 0;
     }
@@ -387,9 +384,18 @@ static int verify_subject(X509* cert, SpiceOpenSSLVerify* verify)
     ret = X509_NAME_cmp(cert_subject, verify->in_subject);
 
     if (ret == 0) {
-        SPICE_DEBUG("subjects match");
+        spice_debug("subjects match");
     } else {
-        SPICE_DEBUG("subjects mismatch");
+        spice_debug("subjects mismatch");
+
+        char *p;
+        p = X509_NAME_oneline(cert_subject, NULL, 0);
+        spice_debug("cert_subject: %s", p);
+        free(p);
+
+        p = X509_NAME_oneline(verify->in_subject, NULL, 0);
+        spice_debug("in_subject:   %s", p);
+        free(p);
     }
 
     return !ret;
@@ -397,18 +403,23 @@ static int verify_subject(X509* cert, SpiceOpenSSLVerify* verify)
 
 static int openssl_verify(int preverify_ok, X509_STORE_CTX *ctx)
 {
-    int depth;
+    int depth, err;
     SpiceOpenSSLVerify *v;
     SSL *ssl;
     X509* cert;
+    char buf[256];
 
     ssl = (SSL*)X509_STORE_CTX_get_ex_data(ctx, SSL_get_ex_data_X509_STORE_CTX_idx());
     v = (SpiceOpenSSLVerify*)SSL_get_app_data(ssl);
 
+    cert = X509_STORE_CTX_get_current_cert(ctx);
+    X509_NAME_oneline(X509_get_subject_name(cert), buf, 256);
     depth = X509_STORE_CTX_get_error_depth(ctx);
+    err = X509_STORE_CTX_get_error(ctx);
     if (depth > 0) {
         if (!preverify_ok) {
-            SPICE_DEBUG("openssl verify failed at depth=%d", depth);
+            spice_warning("openssl verify:num=%d:%s:depth=%d:%s", err,
+                          X509_verify_cert_error_string(err), depth, buf);
             v->all_preverify_ok = 0;
             return 0;
         } else
@@ -416,9 +427,8 @@ static int openssl_verify(int preverify_ok, X509_STORE_CTX *ctx)
     }
 
     /* depth == 0 */
-    cert = X509_STORE_CTX_get_current_cert(ctx);
     if (!cert) {
-        SPICE_DEBUG("failed to get server certificate");
+        spice_debug("failed to get server certificate");
         return 0;
     }