ssl: improve SecureTransport error logging

This improves SecureTransport logging consistency:

- include error code in SSL error when a native backend call fails
- use qt.network.ssl category for debug / warning messages
- do not use duplicate qWarning when error is already reported via QSslError

Change-Id: I52d457b11f0cef2cc3579305e457663b61b92f3f
Reviewed-by: Timur Pocheptsov <Timur.Pocheptsov@digia.com>

1 files changed, 45 insertions, 42 deletions

diff --git a/src/network/ssl/qsslsocket_mac.cpp b/src/network/ssl/qsslsocket_mac.cpp
index 10a9c0b7e9..b83e56c29e 100644
--- a/src/network/ssl/qsslsocket_mac.cpp
+++ b/src/network/ssl/qsslsocket_mac.cpp
@@ -33,6 +33,7 @@
 
 #include "qsslsocket.h"
 
+#include "qssl_p.h"
 #include "qsslsocket_mac_p.h"
 #include "qasn1element_p.h"
 #include "qsslcertificate_p.h"
@@ -93,7 +94,7 @@ static OSStatus _q_SSLRead(QTcpSocket *plainSocket, char *data, size_t *dataLeng
 
     const qint64 bytes = plainSocket->read(data, *dataLength);
 #ifdef QSSLSOCKET_DEBUG
-    qDebug() << Q_FUNC_INFO << plainSocket << "read" << bytes;
+    qCDebug(lcSsl) << plainSocket << "read" << bytes;
 #endif
     if (bytes < 0) {
         *dataLength = 0;
@@ -114,7 +115,7 @@ static OSStatus _q_SSLWrite(QTcpSocket *plainSocket, const char *data, size_t *d
 
     const qint64 bytes = plainSocket->write(data, *dataLength);
 #ifdef QSSLSOCKET_DEBUG
-    qDebug() << Q_FUNC_INFO << plainSocket << "write" << bytes;
+    qCDebug(lcSsl) << plainSocket << "write" << bytes;
 #endif
     if (bytes < 0) {
         *dataLength = 0;
@@ -166,7 +167,7 @@ void QSslSocketPrivate::ensureInitialized()
         if (!s_loadRootCertsOnDemand)
             setDefaultCaCertificates(systemCaCertificates());
     } else {
-        qWarning() << Q_FUNC_INFO << "SSLCreateContext failed";
+        qCWarning(lcSsl) << "SSLCreateContext failed";
         s_loadedCiphersAndCerts = false;
     }
 
@@ -225,7 +226,7 @@ QList<QSslCertificate> QSslSocketPrivate::systemCaCertificates()
         }
     } else {
        // no detailed error handling here
-       qWarning("could not retrieve system CA certificates");
+       qCWarning(lcSsl) << "SecTrustSettingsCopyCertificates failed:" << status;
     }
 #endif
     return systemCerts;
@@ -244,7 +245,7 @@ QSslSocketBackendPrivate::~QSslSocketBackendPrivate()
 void QSslSocketBackendPrivate::continueHandshake()
 {
 #ifdef QSSLSOCKET_DEBUG
-    qDebug() << Q_FUNC_INFO << plainSocket << "connection encrypted";
+    qCDebug(lcSsl) << plainSocket << "connection encrypted";
 #endif
     Q_Q(QSslSocket);
     connectionEncrypted = true;
@@ -291,8 +292,7 @@ QSsl::SslProtocol QSslSocketBackendPrivate::sessionProtocol() const
     SSLProtocol protocol = kSSLProtocolUnknown;
     const OSStatus err = SSLGetNegotiatedProtocolVersion(context, &protocol);
     if (err != noErr) {
-        qWarning() << Q_FUNC_INFO << "SSLGetNegotiatedProtocolVersion failed:"
-                   << int(err);
+        qCWarning(lcSsl) << "SSLGetNegotiatedProtocolVersion failed:" << err;
         return QSsl::UnknownProtocol;
     }
 
@@ -356,9 +356,12 @@ void QSslSocketBackendPrivate::transmit()
             const size_t nextDataBlockSize = writeBuffer.nextDataBlockSize();
             size_t writtenBytes = 0;
             const OSStatus err = SSLWrite(context, writeBuffer.readPointer(), nextDataBlockSize, &writtenBytes);
+#ifdef QSSLSOCKET_DEBUG
+            qCDebug(lcSsl) << plainSocket << "SSLWrite returned" << err;
+#endif
             if (err != noErr && err != errSSLWouldBlock) {
-                qWarning() << Q_FUNC_INFO << "SSL write failed with error:" << int(err);
-                setError("SSL write failed", QAbstractSocket::SslInternalError);
+                setError(QStringLiteral("SSLWrite failed: %1").arg(err),
+                         QAbstractSocket::SslInternalError);
                 break;
             }
 
@@ -387,14 +390,17 @@ void QSslSocketBackendPrivate::transmit()
             size_t readBytes = 0;
             data.resize(4096);
             const OSStatus err = SSLRead(context, data.data(), data.size(), &readBytes);
+#ifdef QSSLSOCKET_DEBUG
+            qCDebug(lcSsl) << plainSocket << "SSLRead returned" << err;
+#endif
             if (err == errSSLClosedGraceful) {
                 shutdown = true; // the other side shut down, make sure we do not send shutdown ourselves
                 setError(QSslSocket::tr("The TLS/SSL connection has been closed"),
                          QAbstractSocket::RemoteHostClosedError);
                 break;
             } else if (err != noErr && err != errSSLWouldBlock) {
-                qWarning() << Q_FUNC_INFO << "SSLRead failed with:" << int(err);
-                setError("SSL read failed", QAbstractSocket::SslInternalError);
+                setError(QStringLiteral("SSLRead failed: %1").arg(err),
+                         QAbstractSocket::SslInternalError);
                 break;
             }
 
@@ -601,7 +607,7 @@ QSslCipher QSslSocketBackendPrivate::QSslCipher_from_SSLCipherSuite(SSLCipherSui
         } else if (ciph.d->name.startsWith("ECDH-") || ciph.d->name.startsWith("ECDHE-")) {
             ciph.d->keyExchangeMethod = QLatin1String("ECDH");
         } else {
-            qWarning() << Q_FUNC_INFO << "Unknown Kx" << ciph.d->name;
+            qCWarning(lcSsl) << "Unknown Kx" << ciph.d->name;
         }
 
         if (bits.size() == 2 || bits.size() == 3) {
@@ -611,7 +617,7 @@ QSslCipher QSslSocketBackendPrivate::QSslCipher_from_SSLCipherSuite(SSLCipherSui
         } else if (ciph.d->name.contains("-RSA-")) {
             ciph.d->authenticationMethod = QLatin1String("RSA");
         } else {
-            qWarning() << Q_FUNC_INFO << "Unknown Au" << ciph.d->name;
+            qCWarning(lcSsl) << "Unknown Au" << ciph.d->name;
         }
 
         if (ciph.d->name.contains("RC4-")) {
@@ -633,7 +639,7 @@ QSslCipher QSslSocketBackendPrivate::QSslCipher_from_SSLCipherSuite(SSLCipherSui
         } else if (ciph.d->name.contains("NULL-")) {
             ciph.d->encryptionMethod = QLatin1String("NULL");
         } else {
-            qWarning() << Q_FUNC_INFO << "Unknown Enc" << ciph.d->name;
+            qCWarning(lcSsl) << "Unknown Enc" << ciph.d->name;
         }
     }
     return ciph;
@@ -652,7 +658,6 @@ bool QSslSocketBackendPrivate::initSslContext()
 
     context = SSLCreateContext(Q_NULLPTR, side, kSSLStreamType);
     if (!context) {
-        qWarning() << Q_FUNC_INFO << "SSLCreateContext failed";
         setError("SSLCreateContext failed", QAbstractSocket::SslInternalError);
         return false;
     }
@@ -660,9 +665,9 @@ bool QSslSocketBackendPrivate::initSslContext()
     const OSStatus err = SSLSetIOFuncs(context, reinterpret_cast<SSLReadFunc>(&_q_SSLRead),
                                        reinterpret_cast<SSLWriteFunc>(&_q_SSLWrite));
     if (err != noErr) {
-        qWarning() << Q_FUNC_INFO << "SSLSetIOFuncs failed with error " << int(err);
         destroySslContext();
-        setError("SSLSetIOFuncs failed", QAbstractSocket::SslInternalError);
+        setError(QStringLiteral("SSLSetIOFuncs failed: %1").arg(err),
+                 QAbstractSocket::SslInternalError);
         return false;
     }
 
@@ -680,7 +685,6 @@ bool QSslSocketBackendPrivate::initSslContext()
     }
 
     if (!setSessionProtocol()) {
-        qWarning() << Q_FUNC_INFO << "failed to set protocol version";
         destroySslContext();
         setError("Failed to set protocol version", QAbstractSocket::SslInternalError);
         return false;
@@ -693,7 +697,6 @@ bool QSslSocketBackendPrivate::initSslContext()
         // But for OS X versions below 10.8 we have to do it explicitly:
         const OSStatus err = SSLSetEnableCertVerify(context, false);
         if (err != noErr) {
-            qWarning() << Q_FUNC_INFO << "SSLSetEnableCertVerify failed:" << int(err);
             destroySslContext();
             setError(QStringLiteral("SSLSetEnableCertVerify failed: %1").arg(err),
                      QSslSocket::SslInternalError);
@@ -716,7 +719,6 @@ bool QSslSocketBackendPrivate::initSslContext()
             err = SSLSetSessionOption(context, kSSLSessionOptionBreakOnCertRequested, true);
 
         if (err != noErr) {
-            qWarning() << Q_FUNC_INFO << "SSLSetSessionOption failed:" << int(err);
             destroySslContext();
             setError(QStringLiteral("SSLSetSessionOption failed: %1").arg(err),
                      QSslSocket::SslInternalError);
@@ -734,7 +736,6 @@ bool QSslSocketBackendPrivate::initSslContext()
             }
 
             if (err != noErr) {
-                qWarning() << Q_FUNC_INFO << "failed to set SSL context option in server mode";
                 destroySslContext();
                 setError(QStringLiteral("failed to set SSL context option in server mode: %1").arg(err),
                          QAbstractSocket::SslInternalError);
@@ -786,7 +787,7 @@ bool QSslSocketBackendPrivate::setSessionCertificate(QString &errorDescription,
         OSStatus err = SecPKCS12Import(pkcs12, options, &items);
         if (err != noErr) {
 #ifdef QSSLSOCKET_DEBUG
-            qWarning() << Q_FUNC_INFO << plainSocket
+            qCWarning(lcSsl) << plainSocket
                        << QStringLiteral("SecPKCS12Import failed: %1").arg(err);
 #endif
             errorCode = QAbstractSocket::SslInvalidUserDataError;
@@ -796,7 +797,7 @@ bool QSslSocketBackendPrivate::setSessionCertificate(QString &errorDescription,
 
         if (!CFArrayGetCount(items)) {
 #ifdef QSSLSOCKET_DEBUG
-            qWarning() << Q_FUNC_INFO << plainSocket << "SecPKCS12Import returned no items";
+            qCWarning(lcSsl) << plainSocket << "SecPKCS12Import returned no items";
 #endif
             errorCode = QAbstractSocket::SslInvalidUserDataError;
             errorDescription = QStringLiteral("SecPKCS12Import returned no items");
@@ -807,7 +808,7 @@ bool QSslSocketBackendPrivate::setSessionCertificate(QString &errorDescription,
         SecIdentityRef identity = (SecIdentityRef)CFDictionaryGetValue(import, kSecImportItemIdentity);
         if (!identity) {
 #ifdef QSSLSOCKET_DEBUG
-            qWarning() << Q_FUNC_INFO << plainSocket << "SecPKCS12Import returned no identity";
+            qCWarning(lcSsl) << plainSocket << "SecPKCS12Import returned no identity";
 #endif
             errorCode = QAbstractSocket::SslInvalidUserDataError;
             errorDescription = QStringLiteral("SecPKCS12Import returned no identity");
@@ -832,7 +833,7 @@ bool QSslSocketBackendPrivate::setSessionCertificate(QString &errorDescription,
         err = SSLSetCertificate(context, certs);
         if (err != noErr) {
 #ifdef QSSLSOCKET_DEBUG
-            qWarning() << Q_FUNC_INFO << plainSocket
+            qCWarning(lcSsl) << plainSocket
                        << QStringLiteral("Cannot set certificate and key: %1").arg(err);
 #endif
             errorCode = QAbstractSocket::SslInvalidUserDataError;
@@ -856,41 +857,41 @@ bool QSslSocketBackendPrivate::setSessionProtocol()
     //     return errSSLIllegalParam;
     // where MINIMUM_STREAM_VERSION is SSL_Version_3_0, MAXIMUM_STREAM_VERSION is TLS_Version_1_2.
     if (configuration.protocol == QSsl::SslV2) {
-        qDebug() << Q_FUNC_INFO << "protocol QSsl::SslV2 is disabled";
+        qCDebug(lcSsl) << "protocol QSsl::SslV2 is disabled";
         return false;
     }
 
     if (configuration.protocol == QSsl::SslV3) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : SSLv3";
+        qCDebug(lcSsl) << plainSocket << "requesting : SSLv3";
 #endif
         err = SSLSetProtocolVersionMin(context, kSSLProtocol3);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kSSLProtocol3);
     } else if (configuration.protocol == QSsl::TlsV1_0) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1.0";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1.0";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol1);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol1);
     } else if (configuration.protocol == QSsl::TlsV1_1) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1.1";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1.1";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol11);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol11);
     } else if (configuration.protocol == QSsl::TlsV1_2) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol12);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::AnyProtocol) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : any";
+        qCDebug(lcSsl) << plainSocket << "requesting : any";
 #endif
         // kSSLProtocol3, since kSSLProtocol2 is disabled:
         err = SSLSetProtocolVersionMin(context, kSSLProtocol3);
@@ -898,41 +899,43 @@ bool QSslSocketBackendPrivate::setSessionProtocol()
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::TlsV1SslV3) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : SSLv3 - TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : SSLv3 - TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kSSLProtocol3);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::SecureProtocols) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1 - TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1 - TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol1);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::TlsV1_0OrLater) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1 - TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1 - TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol1);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::TlsV1_1OrLater) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1.1 - TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1.1 - TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol11);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else if (configuration.protocol == QSsl::TlsV1_2OrLater) {
 #ifdef QSSLSOCKET_DEBUG
-        qDebug() << Q_FUNC_INFO << plainSocket << "requesting : TLSv1.2";
+        qCDebug(lcSsl) << plainSocket << "requesting : TLSv1.2";
 #endif
         err = SSLSetProtocolVersionMin(context, kTLSProtocol12);
         if (err == noErr)
             err = SSLSetProtocolVersionMax(context, kTLSProtocol12);
     } else {
-        qDebug() << Q_FUNC_INFO << "no protocol version found in the configuration";
+#ifdef QSSLSOCKET_DEBUG
+        qCDebug(lcSsl) << plainSocket << "no protocol version found in the configuration";
+#endif
         return false;
     }
 
@@ -1002,7 +1005,8 @@ bool QSslSocketBackendPrivate::verifyPeerTrust()
         if (err != noErr) {
             // We can not ignore this, it's not even about trust verification
             // probably ...
-            setError("SecTrustEvaluate failed", QAbstractSocket::SslHandshakeFailedError);
+            setError(QStringLiteral("SecTrustEvaluate failed: %1").arg(err),
+                     QAbstractSocket::SslHandshakeFailedError);
             plainSocket->disconnectFromHost();
             return false;
         }
@@ -1137,7 +1141,7 @@ bool QSslSocketBackendPrivate::startHandshake()
 
     OSStatus err = SSLHandshake(context);
 #ifdef QSSLSOCKET_DEBUG
-    qDebug() << Q_FUNC_INFO << plainSocket << "SSLHandhake returned" << err;
+    qCDebug(lcSsl) << plainSocket << "SSLHandhake returned" << err;
 #endif
 
     if (err == errSSLWouldBlock) {
@@ -1158,7 +1162,6 @@ bool QSslSocketBackendPrivate::startHandshake()
         // setSessionCertificate does not fail if we have no certificate.
         // Failure means a real error (invalid certificate, no private key, etc).
         if (!setSessionCertificate(errorDescription, errorCode)) {
-            qWarning() << Q_FUNC_INFO << "Failed to provide a client certificate";
             setError(errorDescription, errorCode);
             return false;
         } else {
@@ -1174,7 +1177,7 @@ bool QSslSocketBackendPrivate::startHandshake()
             return startHandshake();
         }
 
-        setError(QStringLiteral("Error during SSL handshake: %1").arg(err),
+        setError(QStringLiteral("SSLHandshake failed: %1").arg(err),
                  QAbstractSocket::SslHandshakeFailedError);
         plainSocket->disconnectFromHost();
         return false;
@@ -1182,7 +1185,7 @@ bool QSslSocketBackendPrivate::startHandshake()
 
     // Connection aborted during handshake phase.
     if (q->state() != QAbstractSocket::ConnectedState) {
-        qDebug() << Q_FUNC_INFO << "connection aborted";
+        qCDebug(lcSsl) << "connection aborted";
         return false;
     }