TT#78203 add SRTP debug options

closes #956

Change-Id: I751f6bc1ea9228b257f6258dbb1927276db10c99

daemon/crypto.c

@@ -19,7 +19,7 @@
 
 
 
-#define CRYPTO_DEBUG 0
+GString __thread *crypto_debug_string;
 
 
 
@@ -424,27 +424,26 @@ int crypto_gen_session_key(struct crypto_context *c, str *out, unsigned char lab
 
 	prf_n(out, c->params.master_key, c->params.crypto_suite->lib_cipher_ptr, x);
 
-#if CRYPTO_DEBUG
-	ilog(LOG_DEBUG, "Generated session key: master key "
-			"%02x%02x%02x%02x..., "
-			"master salt "
-			"%02x%02x%02x%02x..., "
-			"label %02x, length %i, result "
-			"%02x%02x%02x%02x...",
-			c->params.master_key[0],
-			c->params.master_key[1],
-			c->params.master_key[2],
-			c->params.master_key[3],
-			c->params.master_salt[0],
-			c->params.master_salt[1],
-			c->params.master_salt[2],
-			c->params.master_salt[3],
-			label, out->len,
-			(unsigned char) out->s[0],
-			(unsigned char) out->s[1],
-			(unsigned char) out->s[2],
-			(unsigned char) out->s[3]);
-#endif
+	if (rtpe_config.debug_srtp)
+		ilog(LOG_DEBUG, "Generated session key: master key "
+				"%02x%02x%02x%02x..., "
+				"master salt "
+				"%02x%02x%02x%02x..., "
+				"label %02x, length %i, result "
+				"%02x%02x%02x%02x...",
+				c->params.master_key[0],
+				c->params.master_key[1],
+				c->params.master_key[2],
+				c->params.master_key[3],
+				c->params.master_salt[0],
+				c->params.master_salt[1],
+				c->params.master_salt[2],
+				c->params.master_salt[3],
+				label, out->len,
+				(unsigned char) out->s[0],
+				(unsigned char) out->s[1],
+				(unsigned char) out->s[2],
+				(unsigned char) out->s[3]);
 
 	return 0;
 }
@@ -772,3 +771,10 @@ void crypto_init_main() {
 		}
 	}
 }
+
+void __crypto_debug_printf(const char *fmt, ...) {
+	va_list va;
+	va_start(va, fmt);
+	g_string_append_vprintf(crypto_debug_string, fmt, va);
+	va_end(va);
+}

daemon/dtls.c

@@ -617,20 +617,6 @@ found:
 	i += cs->master_salt_len;
 	memcpy(server.master_salt, &keys[i], cs->master_salt_len);
 
-	__DBG("SRTP keys negotiated: "
-			"c-m: %02x%02x%02x%02x%02x%02x%02x%02x "
-			"c-s: %02x%02x%02x%02x%02x%02x%02x%02x "
-			"s-m: %02x%02x%02x%02x%02x%02x%02x%02x "
-			"s-s: %02x%02x%02x%02x%02x%02x%02x%02x",
-			client.master_key[0], client.master_key[1], client.master_key[2], client.master_key[3],
-			client.master_key[4], client.master_key[5], client.master_key[6], client.master_key[7],
-			client.master_salt[0], client.master_salt[1], client.master_salt[2], client.master_salt[3],
-			client.master_salt[4], client.master_salt[5], client.master_salt[6], client.master_salt[7],
-			server.master_key[0], server.master_key[1], server.master_key[2], server.master_key[3],
-			server.master_key[4], server.master_key[5], server.master_key[6], server.master_key[7],
-			server.master_salt[0], server.master_salt[1], server.master_salt[2], server.master_salt[3],
-			server.master_salt[4], server.master_salt[5], server.master_salt[6], server.master_salt[7]);
-
 	ilog(LOG_INFO, "DTLS-SRTP successfully negotiated");
 
 	if (d->active) {

daemon/main.c

@@ -379,6 +379,7 @@ static void options(int *argc, char ***argv) {
 		{ "endpoint-learning",0,0,G_OPTION_ARG_STRING,	&endpoint_learning,	"RTP endpoint learning algorithm",	"delayed|immediate|off|heuristic"	},
 		{ "jitter-buffer",0, 0,	G_OPTION_ARG_INT,	&rtpe_config.jb_length,	"Size of jitter buffer",		"INT" },
 		{ "jb-clock-drift",0,0,	G_OPTION_ARG_NONE,	&rtpe_config.jb_clock_drift,"Compensate for source clock drift",NULL },
+		{ "debug-srtp",0,0,	G_OPTION_ARG_NONE,	&rtpe_config.debug_srtp,"Log raw encryption details for SRTP",	NULL },
 
 		{ NULL, }
 	};

daemon/rtcp.c

@@ -843,10 +843,18 @@ int rtcp_avp2savp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 	if (check_session_keys(c))
 		return -1;
 
+	crypto_debug_init(1);
+	crypto_debug_printf("RTCP SSRC %" PRIx32 ", idx %" PRIu64 ", plain pl: ",
+			rtcp->ssrc, ssrc_ctx->srtcp_index);
+	crypto_debug_dump(&payload);
+
 	if (!c->params.session_params.unencrypted_srtcp && crypto_encrypt_rtcp(c, rtcp, &payload,
 				ssrc_ctx->srtcp_index))
 		return -1;
 
+	crypto_debug_printf(", enc pl: ");
+	crypto_debug_dump(&payload);
+
 	idx = (void *) s->s + s->len;
 	*idx = htonl((c->params.session_params.unencrypted_srtcp ? 0ULL : 0x80000000ULL) |
 			ssrc_ctx->srtcp_index++);
@@ -857,8 +865,12 @@ int rtcp_avp2savp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 	rtp_append_mki(s, c);
 
 	c->params.crypto_suite->hash_rtcp(c, s->s + s->len, &to_auth);
+	crypto_debug_printf(", auth: ");
+	crypto_debug_dump_raw(s->s + s->len, c->params.crypto_suite->srtcp_auth_tag);
 	s->len += c->params.crypto_suite->srtcp_auth_tag;
 
+	crypto_debug_finish();
+
 	return 1;
 }
 
@@ -878,11 +890,17 @@ int rtcp_savp2avp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 	if (check_session_keys(c))
 		return -1;
 
+	crypto_debug_init(1);
+
 	if (srtp_payloads(&to_auth, &to_decrypt, &auth_tag, NULL,
 			c->params.crypto_suite->srtcp_auth_tag, c->params.mki_len,
 			s, &payload))
 		return -1;
 
+	crypto_debug_printf("RTCP SSRC %" PRIx32 ", enc pl: ",
+			rtcp->ssrc);
+	crypto_debug_dump(&to_decrypt);
+
 	err = "short packet";
 	if (to_decrypt.len < sizeof(idx))
 		goto error;
@@ -890,8 +908,16 @@ int rtcp_savp2avp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 	idx_p = (void *) to_decrypt.s + to_decrypt.len;
 	idx = ntohl(*idx_p);
 
+	crypto_debug_printf(", idx %" PRIu32, idx);
+
 	assert(sizeof(hmac) >= auth_tag.len);
 	c->params.crypto_suite->hash_rtcp(c, hmac, &to_auth);
+
+	crypto_debug_printf(", rcv hmac: ");
+	crypto_debug_dump(&auth_tag);
+	crypto_debug_printf(", calc hmac: ");
+	crypto_debug_dump_raw(hmac, auth_tag.len);
+
 	err = "authentication failed";
 	if (str_memcmp(&auth_tag, hmac))
 		goto error;
@@ -899,11 +925,16 @@ int rtcp_savp2avp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 	if ((idx & 0x80000000ULL)) {
 		if (crypto_decrypt_rtcp(c, rtcp, &to_decrypt, idx & 0x7fffffffULL))
 			return -1;
+
+		crypto_debug_printf(", dec pl: ");
+		crypto_debug_dump(&to_decrypt);
 	}
 
 	*s = to_auth;
 	s->len -= sizeof(idx);
 
+	crypto_debug_finish();
+
 	return 0;
 
 error:

daemon/rtp.c

@@ -49,6 +49,10 @@ static u_int64_t packet_index(struct ssrc_ctx *ssrc_ctx, struct rtp_header *rtp)
 	u_int16_t seq;
 
 	seq = ntohs(rtp->seq_num);
+
+	crypto_debug_init((seq & 0x1ff) == (ssrc_ctx->parent->h.ssrc & 0x1ff));
+	crypto_debug_printf("SSRC %" PRIx32 ", seq %" PRIu16, ssrc_ctx->parent->h.ssrc, seq);
+
 	/* rfc 3711 section 3.3.1 */
 	if (G_UNLIKELY(!ssrc_ctx->srtp_index))
 		ssrc_ctx->srtp_index = seq;
@@ -58,6 +62,9 @@ static u_int64_t packet_index(struct ssrc_ctx *ssrc_ctx, struct rtp_header *rtp)
 	u_int32_t roc = (ssrc_ctx->srtp_index & 0xffffffff0000ULL) >> 16;
 	u_int32_t v = 0;
 
+	crypto_debug_printf(", prev seq %" PRIu64 ", s_l %" PRIu16 ", ROC %" PRIu32,
+			ssrc_ctx->srtp_index, s_l, roc);
+
 	if (s_l < 0x8000) {
 		if (((seq - s_l) > 0x8000) && roc > 0)
 			v = (roc - 1) % 0x10000;
@@ -71,6 +78,9 @@ static u_int64_t packet_index(struct ssrc_ctx *ssrc_ctx, struct rtp_header *rtp)
 	}
 
 	ssrc_ctx->srtp_index = (u_int64_t)(((v << 16) | seq) & 0xffffffffffffULL);
+
+	crypto_debug_printf(", v %" PRIu32 ", ext seq %" PRIu64, v, ssrc_ctx->srtp_index);
+
 	return ssrc_ctx->srtp_index;
 }
 
@@ -84,6 +94,9 @@ void rtp_append_mki(str *s, struct crypto_context *c) {
 	p = s->s + s->len;
 	memcpy(p, c->params.mki, c->params.mki_len);
 	s->len += c->params.mki_len;
+
+	crypto_debug_printf(", MKI: ");
+	crypto_debug_dump_raw(p, c->params.mki_len);
 }
 
 /* rfc 3711, section 3.3 */
@@ -101,19 +114,29 @@ int rtp_avp2savp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 
 	index = packet_index(ssrc_ctx, rtp);
 
+	crypto_debug_printf(", plain pl: ");
+	crypto_debug_dump(&payload);
+
 	/* rfc 3711 section 3.1 */
 	if (!c->params.session_params.unencrypted_srtp && crypto_encrypt_rtp(c, rtp, &payload, index))
 		return -1;
 
+	crypto_debug_printf(", enc pl: ");
+	crypto_debug_dump(&payload);
+
 	to_auth = *s;
 
 	rtp_append_mki(s, c);
 
 	if (!c->params.session_params.unauthenticated_srtp && c->params.crypto_suite->srtp_auth_tag) {
 		c->params.crypto_suite->hash_rtp(c, s->s + s->len, &to_auth, index);
+		crypto_debug_printf(", auth: ");
+		crypto_debug_dump_raw(s->s + s->len, c->params.crypto_suite->srtp_auth_tag);
 		s->len += c->params.crypto_suite->srtp_auth_tag;
 	}
 
+	crypto_debug_finish();
+
 	return 0;
 }
 
@@ -138,30 +161,51 @@ int rtp_savp2avp(str *s, struct crypto_context *c, struct ssrc_ctx *ssrc_ctx) {
 			s, &payload))
 		return -1;
 
+	crypto_debug_printf(", enc pl: ");
+	crypto_debug_dump(&to_decrypt);
+
 	if (!auth_tag.len)
 		goto decrypt;
 
 	/* authenticate */
 	assert(sizeof(hmac) >= auth_tag.len);
 	c->params.crypto_suite->hash_rtp(c, hmac, &to_auth, index);
+
+	crypto_debug_printf(", rcv hmac: ");
+	crypto_debug_dump(&auth_tag);
+	crypto_debug_printf(", calc hmac: ");
+	crypto_debug_dump_raw(hmac, auth_tag.len);
+
 	if (!str_memcmp(&auth_tag, hmac))
 		goto decrypt;
 	/* possible ROC mismatch, attempt to guess */
 	/* first, let's see if we missed a rollover */
 	index += 0x10000;
 	c->params.crypto_suite->hash_rtp(c, hmac, &to_auth, index);
+
+	crypto_debug_printf(", calc hmac 2: ");
+	crypto_debug_dump_raw(hmac, auth_tag.len);
+
 	if (!str_memcmp(&auth_tag, hmac))
 		goto decrypt_idx;
 	/* or maybe we did a rollover too many */
 	if (index >= 0x20000) {
 		index -= 0x20000;
 		c->params.crypto_suite->hash_rtp(c, hmac, &to_auth, index);
+
+		crypto_debug_printf(", calc hmac 3: ");
+		crypto_debug_dump_raw(hmac, auth_tag.len);
+
 		if (!str_memcmp(&auth_tag, hmac))
 			goto decrypt_idx;
 	}
 	/* last guess: reset ROC to zero */
 	index &= 0xffff;
 	c->params.crypto_suite->hash_rtp(c, hmac, &to_auth, index);
+
+	crypto_debug_printf(", calc hmac 4: ");
+	crypto_debug_dump_raw(hmac, auth_tag.len);
+
 	if (!str_memcmp(&auth_tag, hmac))
 		goto decrypt_idx;
 	goto error;
@@ -172,8 +216,13 @@ decrypt:
 	if (!c->params.session_params.unencrypted_srtp && crypto_decrypt_rtp(c, rtp, &to_decrypt, index))
 		return -1;
 
+	crypto_debug_printf(", dec pl: ");
+	crypto_debug_dump(&to_decrypt);
+
 	*s = to_auth;
 
+	crypto_debug_finish();
+
 	return 0;
 
 error:

daemon/rtpengine.pod

@@ -681,6 +681,14 @@ userspace operation.
 
 Enable clock drift compensation for the jitter buffer.
 
+=item B<--debug-srtp>
+
+Enable extra log messages to help debug SRTP issues. Per-packet details such as
+sequence numbers, ROC, payloads (plain text and encrypted), authentication
+tags, etc are recorded to the log. Every RTCP packet is logged in this way,
+while every 512th RTP packet is logged. Only applies to packets
+forwarded/processed in userspace.
+
 =back
 
 =head1 INTERFACES

include/crypto.h

@@ -101,6 +101,8 @@ struct crypto_context {
 extern const struct crypto_suite *crypto_suites;
 extern const unsigned int num_crypto_suites;
 
+extern GString __thread *crypto_debug_string;
+
 
 
 void crypto_init_main(void);
@@ -203,5 +205,41 @@ INLINE void crypto_params_sdes_queue_clear(GQueue *q) {
 }
 
 
+#include "main.h"
+#include "log.h"
+
+
+INLINE void crypto_debug_init(int flag) {
+	if (!rtpe_config.debug_srtp)
+		return;
+	if (crypto_debug_string)
+		g_string_free(crypto_debug_string, TRUE);
+	crypto_debug_string = NULL;
+	if (!flag)
+		return;
+	crypto_debug_string = g_string_new("");
+}
+void __crypto_debug_printf(const char *fmt, ...) __attribute__((format(printf,1,2)));
+#define crypto_debug_printf(f, ...) \
+	if (rtpe_config.debug_srtp && crypto_debug_string) \
+		__crypto_debug_printf(f, ##__VA_ARGS__)
+INLINE void crypto_debug_dump_raw(const char *b, int len) {
+	for (int i = 0; i < len; i++)
+		crypto_debug_printf("%02" PRIx8, (unsigned char) b[i]);
+}
+INLINE void crypto_debug_dump(const str *s) {
+	crypto_debug_dump_raw(s->s, s->len);
+}
+INLINE void crypto_debug_finish(void) {
+	if (!rtpe_config.debug_srtp)
+		return;
+	if (!crypto_debug_string)
+		return;
+	ilog(LOG_NOTICE, "Crypto debug: %.*s", (int) crypto_debug_string->len, crypto_debug_string->str);
+	g_string_free(crypto_debug_string, TRUE);
+	crypto_debug_string = NULL;
+}
+
+
 
 #endif

include/main.h

@@ -95,6 +95,7 @@ struct rtpengine_config {
 	enum endpoint_learning	endpoint_learning;
 	int                     jb_length;
 	int                     jb_clock_drift;
+	int			debug_srtp;
 };