diff --git a/daemon/crypto.c b/daemon/crypto.c index 7b3e39611..5d9ec2c6a 100644 --- a/daemon/crypto.c +++ b/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); +} diff --git a/daemon/dtls.c b/daemon/dtls.c index fb27187d4..5806ae8b3 100644 --- a/daemon/dtls.c +++ b/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) { diff --git a/daemon/main.c b/daemon/main.c index ca18d0fe0..20b5be5f0 100644 --- a/daemon/main.c +++ b/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, } }; diff --git a/daemon/rtcp.c b/daemon/rtcp.c index dc3342804..af3a55898 100644 --- a/daemon/rtcp.c +++ b/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: diff --git a/daemon/rtp.c b/daemon/rtp.c index 4d90547df..db874a293 100644 --- a/daemon/rtp.c +++ b/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: diff --git a/daemon/rtpengine.pod b/daemon/rtpengine.pod index 9831c041e..2e77961f2 100644 --- a/daemon/rtpengine.pod +++ b/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 diff --git a/include/crypto.h b/include/crypto.h index d4d9c03e3..2b632be60 100644 --- a/include/crypto.h +++ b/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 diff --git a/include/main.h b/include/main.h index 5ca67d486..4f3e9598a 100644 --- a/include/main.h +++ b/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; };