tls_debug.c

tls_debug.c

#include <time.h>
#include <sys/time.h>
#include <openssl/bio.h>
#include <openssl/ssl.h>
#include <tls.h>
#include "tls_internal.h"

#define TLS_DEBUG_LOG_LEVEL_NONE		0
#define TLS_DEBUG_LOG_LEVEL_MSG_ONLY		1
#define TLS_DEBUG_LOG_LEVEL_MSG_WITH_DUMP	2

static int tls_debug_log_level = TLS_DEBUG_LOG_LEVEL_NONE;

static BIO *bio_debug_out = NULL;

static void msg_cb(int write_p, int version, int content_type,
    const void *buf, size_t len, SSL * ssl, void *arg);
static void tlsext_cb(SSL * s, int client_server, int type,
    unsigned char *data, int len, void *arg);
static char * get_timestamp();

int
tls_debug_set_log_level(struct tls *ctx, int debug_log_level)
{
	if ((ctx->flags & (TLS_CLIENT | TLS_SERVER_CONN)) == 0) {
		tls_set_errorx(ctx, "invalid operation for context");
		return -1;
	}

	if (ctx->ssl_conn == NULL) {
		tls_set_errorx(ctx, "invalid operation before ssl connection");
		return -1;
	}

	if (debug_log_level < TLS_DEBUG_LOG_LEVEL_NONE ||
	    debug_log_level > TLS_DEBUG_LOG_LEVEL_MSG_WITH_DUMP) {
		tls_set_errorx(ctx, "invalid debug log level");
		return -1;
	}

	tls_debug_log_level = debug_log_level;

	if (tls_debug_log_level > TLS_DEBUG_LOG_LEVEL_NONE) {
		if (bio_debug_out == NULL)
			bio_debug_out = BIO_new_fp(stdout, BIO_NOCLOSE);

		SSL_set_msg_callback(ctx->ssl_conn, msg_cb);
		SSL_set_msg_callback_arg(ctx->ssl_conn, bio_debug_out);
		SSL_set_tlsext_debug_callback(ctx->ssl_conn, tlsext_cb);
		SSL_set_tlsext_debug_arg(ctx->ssl_conn, bio_debug_out);

	} else {
		if (bio_debug_out != NULL) {
			BIO_free(bio_debug_out);
			bio_debug_out = NULL;
		}

		SSL_set_msg_callback(ctx->ssl_conn, NULL);
		SSL_set_msg_callback_arg(ctx->ssl_conn, NULL);
		SSL_set_tlsext_debug_callback(ctx->ssl_conn, NULL);
		SSL_set_tlsext_debug_arg(ctx->ssl_conn, NULL);
	}

	return 0;
}

static void
msg_cb(int write_p, int version, int content_type,
    const void *buf, size_t len, SSL * ssl, void *arg)
{
	BIO *bio = arg;
	const char *str_write_p, *str_version, *str_content_type = "",
	    *str_details1 = "", *str_details2 = "";

	str_write_p = write_p ? ">>>" : "<<<";

	switch (version) {
	case SSL2_VERSION:
		str_version = "SSLv2.0";
		break;
	case SSL3_VERSION:
		str_version = "SSLv3.0";
		break;
	case TLS1_VERSION:
		str_version = "TLSv1.0";
		break;
	case TLS1_1_VERSION:
		str_version = "TLSv1.1";
		break;
	case TLS1_2_VERSION:
		str_version = "TLSv1.2";
		break;
	case DTLS1_VERSION:
		str_version = "DTLSv1.0";
		break;
	default:
		str_version = "???";
		break;
	}

	if (version == SSL2_VERSION && len > 0) {
		switch (((const unsigned char *) buf)[0]) {
		case SSL2_MT_ERROR:
			str_details1 = "ERROR:";
			if (len < 3)
				break;
			unsigned err = (((const unsigned char *) buf)[1] << 8) +
					((const unsigned char *) buf)[2];
			switch (err) {
			case SSL2_PE_UNDEFINED_ERROR:
				str_details2 = "UNDEFINED-ERROR";
				break;
			case SSL2_PE_NO_CIPHER:
				str_details2 = "NO-CIPHER-ERROR";
				break;
			case SSL2_PE_NO_CERTIFICATE:
				str_details2 = "NO-CERTIFICATE-ERROR";
				break;
			case SSL2_PE_BAD_CERTIFICATE:
				str_details2 = "BAD-CERTIFICATE-ERROR";
				break;
			case SSL2_PE_UNSUPPORTED_CERTIFICATE_TYPE:
				str_details2 = "UNSUPPORTED-CERTIFICATE-TYPE-ERROR";
				break;
			default:
				str_details2 = "???";
				break;
			}
			break;
		case SSL2_MT_CLIENT_HELLO:
			str_details1 = "CLIENT-HELLO";
			break;
		case SSL2_MT_CLIENT_MASTER_KEY:
			str_details1 = "CLIENT-MASTER-KEY";
			break;
		case SSL2_MT_CLIENT_FINISHED:
			str_details1 = "CLIENT-FINISHED";
			break;
		case SSL2_MT_SERVER_HELLO:
			str_details1 = "SERVER-HELLO";
			break;
		case SSL2_MT_SERVER_VERIFY:
			str_details1 = "SERVER-VERIFY";
			break;
		case SSL2_MT_SERVER_FINISHED:
			str_details1 = "SERVER-FINISHED";
			break;
		case SSL2_MT_REQUEST_CERTIFICATE:
			str_details1 = "REQUEST-CERTIFICATE";
			break;
		case SSL2_MT_CLIENT_CERTIFICATE:
			str_details1 = "CLIENT-CERTIFICATE";
			break;
		default:
			str_details1 = "???";
			break;
		}
	}

	if (version == SSL3_VERSION || version == TLS1_VERSION ||
	    version == TLS1_1_VERSION || version == TLS1_2_VERSION ||
	    version == DTLS1_VERSION) {

		switch (content_type) {
		case SSL3_RT_CHANGE_CIPHER_SPEC:
			str_content_type = "ChangeCipherSpec";
			break;
		case SSL3_RT_ALERT:
			str_content_type = "Alert";
			break;
		case SSL3_RT_HANDSHAKE:
			str_content_type = "Handshake";
			break;
		case SSL3_RT_APPLICATION_DATA:
			str_content_type = "ApplicationData";
			break;
		case TLS1_RT_HEARTBEAT:
			str_content_type = "Heartbeat";
			break;
		default:
			str_content_type = "???";
			break;
		}

		if (content_type == SSL3_RT_ALERT && len == 2) {
			switch (((const unsigned char *) buf)[0]) {
			case SSL3_AL_WARNING:
				str_details1 = "warning";
				break;
			case SSL3_AL_FATAL:
				str_details1 = "fatal";
				break;
			default:
				str_details1 = "???";
				break;
			}

			switch (((const unsigned char *) buf)[1]) {
			case SSL3_AD_CLOSE_NOTIFY:
				str_details2 = "close_notify";
				break;
			case SSL3_AD_UNEXPECTED_MESSAGE:
				str_details2 = "unexpected_message";
				break;
			case SSL3_AD_BAD_RECORD_MAC:
				str_details2 = "bad_record_mac";
				break;
			case SSL3_AD_DECOMPRESSION_FAILURE:
				str_details2 = "decompression_failure";
				break;
			case SSL3_AD_HANDSHAKE_FAILURE:
				str_details2 = "handshake_failure";
				break;
			case SSL3_AD_NO_CERTIFICATE:
				str_details2 = "no_certificate";
				break;
			case SSL3_AD_BAD_CERTIFICATE:
				str_details2 = "bad_certificate";
				break;
			case SSL3_AD_UNSUPPORTED_CERTIFICATE:
				str_details2 = "unsupported_certificate";
				break;
			case SSL3_AD_CERTIFICATE_REVOKED:
				str_details2 = "certificate_revoked";
				break;
			case SSL3_AD_CERTIFICATE_EXPIRED:
				str_details2 = "certificate_expired";
				break;
			case SSL3_AD_CERTIFICATE_UNKNOWN:
				str_details2 = "certificate_unknown";
				break;
			case SSL3_AD_ILLEGAL_PARAMETER:
				str_details2 = "illegal_parameter";
				break;
			case TLS1_AD_DECRYPTION_FAILED:
				str_details2 = "decryption_failed";
				break;
			case TLS1_AD_RECORD_OVERFLOW:
				str_details2 = "record_overflow";
				break;
			case TLS1_AD_UNKNOWN_CA:
				str_details2 = "unknown_ca";
				break;
			case TLS1_AD_ACCESS_DENIED:
				str_details2 = "access_denied";
				break;
			case TLS1_AD_DECODE_ERROR:
				str_details2 = "decode_error";
				break;
			case TLS1_AD_DECRYPT_ERROR:
				str_details2 = "decrypt_error";
				break;
			case TLS1_AD_EXPORT_RESTRICTION:
				str_details2 = "export_restriction";
				break;
			case TLS1_AD_PROTOCOL_VERSION:
				str_details2 = "protocol_version";
				break;
			case TLS1_AD_INSUFFICIENT_SECURITY:
				str_details2 = "insufficient_security";
				break;
			case TLS1_AD_INTERNAL_ERROR:
				str_details2 = "internal_error";
				break;
			case TLS1_AD_INAPPROPRIATE_FALLBACK:
				str_details2 = "inappropriate_fallback";
				break;
			case TLS1_AD_USER_CANCELLED:
				str_details2 = "user_canceled";
				break;
			case TLS1_AD_NO_RENEGOTIATION:
				str_details2 = "no_renegotiation";
				break;
			case TLS1_AD_UNSUPPORTED_EXTENSION:
				str_details2 = "unsupported_extension";
				break;
			case TLS1_AD_CERTIFICATE_UNOBTAINABLE:
				str_details2 = "certificate_unobtainable";
				break;
			case TLS1_AD_UNRECOGNIZED_NAME:
				str_details2 = "unrecognized_name";
				break;
			case TLS1_AD_BAD_CERTIFICATE_STATUS_RESPONSE:
				str_details2 = "bad_certificate_status_response";
				break;
			case TLS1_AD_BAD_CERTIFICATE_HASH_VALUE:
				str_details2 = "bad_certificate_hash_value";
				break;
			case TLS1_AD_UNKNOWN_PSK_IDENTITY:
				str_details2 = "unknown_psk_identity";
				break;
			default:
				str_details2 = "???";
				break;
			}
		}

		if (content_type == SSL3_RT_HANDSHAKE && len > 0) {
			switch (((const unsigned char *) buf)[0]) {
			case SSL3_MT_HELLO_REQUEST:
				str_details1 = "HelloRequest";
				break;
			case SSL3_MT_CLIENT_HELLO:
				str_details1 = "ClientHello";
				break;
			case SSL3_MT_SERVER_HELLO:
				str_details1 = "ServerHello";
				break;
			case SSL3_MT_NEWSESSION_TICKET:
				str_details1 = "NewsessionTicket";
				break;
			case SSL3_MT_CERTIFICATE:
				str_details1 = "Certificate";
				break;
			case SSL3_MT_SERVER_KEY_EXCHANGE:
				str_details1 = "ServerKeyExchange";
				break;
			case SSL3_MT_CERTIFICATE_REQUEST:
				str_details1 = "CertificateRequest";
				break;
			case SSL3_MT_SERVER_DONE:
				str_details1 = "ServerDone";
				break;
			case SSL3_MT_CERTIFICATE_VERIFY:
				str_details1 = "CertificateVerify";
				break;
			case SSL3_MT_CLIENT_KEY_EXCHANGE:
				str_details1 = "ClientKeyExchange";
				break;
			case SSL3_MT_FINISHED:
				str_details1 = "Finished";
				break;
			case SSL3_MT_CERTIFICATE_STATUS:
				str_details1 = "CertificateStatus";
				break;
			case SSL3_MT_NEXT_PROTO:
				str_details1 = "NextProto";
				break;
			case DTLS1_MT_HELLO_VERIFY_REQUEST:
				str_details1 = "HelloVerifyRequest";
				break;
			default:
				str_details1 = "???";
				break;
			}
		}
	}

	if (tls_debug_log_level >= TLS_DEBUG_LOG_LEVEL_MSG_ONLY)
		BIO_printf(bio, "%s (msg) %s %s %s len=%d  %s %s\n",
		    get_timestamp(), str_write_p,
		    str_version, str_content_type, (int) len,
		    str_details1, str_details2);

	if (tls_debug_log_level >= TLS_DEBUG_LOG_LEVEL_MSG_WITH_DUMP)
		BIO_dump(bio, (char *) buf, len);

	(void) BIO_flush(bio);
}

static void
tlsext_cb(SSL * s, int client_server, int type,
    unsigned char *data, int len, void *arg)
{
	BIO *bio = arg;
	char *extname;

	switch (type) {
	case TLSEXT_TYPE_server_name:
		extname = "server name";
		break;
	case TLSEXT_TYPE_max_fragment_length:
		extname = "max fragment length";
		break;
	case TLSEXT_TYPE_client_certificate_url:
		extname = "client certificate URL";
		break;
	case TLSEXT_TYPE_trusted_ca_keys:
		extname = "trusted CA keys";
		break;
	case TLSEXT_TYPE_truncated_hmac:
		extname = "truncated HMAC";
		break;
	case TLSEXT_TYPE_status_request:
		extname = "status request";
		break;
	case TLSEXT_TYPE_user_mapping:
		extname = "user mapping";
		break;
	case TLSEXT_TYPE_client_authz:
		extname = "client authz";
		break;
	case TLSEXT_TYPE_server_authz:
		extname = "server authz";
		break;
	case TLSEXT_TYPE_cert_type:
		extname = "cert type";
		break;
	case TLSEXT_TYPE_elliptic_curves:
		extname = "elliptic curves";
		break;
	case TLSEXT_TYPE_ec_point_formats:
		extname = "EC point formats";
		break;
	case TLSEXT_TYPE_srp:
		extname = "SRP";
		break;
	case TLSEXT_TYPE_signature_algorithms:
		extname = "signature algorithms";
		break;
	case TLSEXT_TYPE_use_srtp:
		extname = "use SRTP";
		break;
	case TLSEXT_TYPE_heartbeat:
		extname = "heartbeat";
		break;
	case TLSEXT_TYPE_application_layer_protocol_negotiation:
		extname = "ALPN";
		break;
	case TLSEXT_TYPE_padding:
		extname = "padding";
		break;
	case TLSEXT_TYPE_session_ticket:
		extname = "session ticket";
		break;
	case TLSEXT_TYPE_renegotiate:
		extname = "renegotiation info";
		break;

#ifdef TLSEXT_TYPE_next_proto_neg
	case TLSEXT_TYPE_next_proto_neg:
		extname = "next protocol";
		break;
#endif

	default:
		extname = "unknown";
		break;
	}

	if (tls_debug_log_level >= TLS_DEBUG_LOG_LEVEL_MSG_ONLY)
		BIO_printf(bio, "%s (tlsext) %s \"%s\" (id=%d) len=%d\n",
		    get_timestamp(), client_server ? "server" : "client",
		    extname, type, len);

	if (tls_debug_log_level >= TLS_DEBUG_LOG_LEVEL_MSG_WITH_DUMP)
		BIO_dump(bio, (char *) data, len);

	(void) BIO_flush(bio);
}

static char *
get_timestamp()
{
	static char timestamp[BUFSIZ];
	struct timeval tv;
	struct tm *t;

	gettimeofday(&tv, NULL);
	t = localtime(&tv.tv_sec);
	sprintf(timestamp, "%04d/%02d/%02d %02d:%02d:%02d.%06d",
		t->tm_year + 1900, t->tm_mon + 1, t->tm_mday,
		t->tm_hour, t->tm_min, t->tm_sec, (int)tv.tv_usec);

	return timestamp;
}