RTC: Refine error and log for DTLS

trunk/src/app/srs_app_rtc_conn.cpp

@@ -1058,7 +1058,7 @@ srs_error_t SrsRtcPublishStream::on_rtp(char* data, int nb_data)
         int nb_header = h.nb_bytes();
         const char* body = unprotected_buf + nb_header;
         int nb_body = nb_unprotected_buf - nb_header;
-        return srs_error_wrap(err, "cipher=%u, plaintext=%u, body=%s", nb_data, nb_unprotected_buf,
+        return srs_error_wrap(err, "cipher=%u, plaintext=%u, body=[%s]", nb_data, nb_unprotected_buf,
             srs_string_dumps_hex(body, nb_body, 8).c_str());
     }
 
@@ -1733,7 +1733,7 @@ srs_error_t SrsRtcConnection::on_rtcp(char* data, int nb_data)
 
     SrsRtcpCompound rtcp_compound;
     if(srs_success != (err = rtcp_compound.decode(buffer))) {
-        return srs_error_wrap(err, "decode rtcp plaintext=%u, bytes=%s, at=%s", nb_unprotected_buf,
+        return srs_error_wrap(err, "decode rtcp plaintext=%u, bytes=[%s], at=%s", nb_unprotected_buf,
             srs_string_dumps_hex(unprotected_buf, nb_unprotected_buf, 8).c_str(),
             srs_string_dumps_hex(buffer->head(), buffer->left(), 8).c_str());
     }
@@ -1744,7 +1744,7 @@ srs_error_t SrsRtcConnection::on_rtcp(char* data, int nb_data)
         SrsAutoFree(SrsRtcpCommon, rtcp);
 
         if(srs_success != err) {
-            return srs_error_wrap(err, "cipher=%u, plaintext=%u, bytes=%s, rtcp=(%u,%u,%u,%u)", nb_data, nb_unprotected_buf,
+            return srs_error_wrap(err, "cipher=%u, plaintext=%u, bytes=[%s], rtcp=(%u,%u,%u,%u)", nb_data, nb_unprotected_buf,
                 srs_string_dumps_hex(unprotected_buf, nb_unprotected_buf, 8).c_str(),
                 rtcp->get_rc(), rtcp->type(), rtcp->get_ssrc(), rtcp->size());
         }

trunk/src/app/srs_app_rtc_dtls.cpp

@@ -32,6 +32,7 @@ using namespace std;
 #include <srs_app_config.hpp>
 #include <srs_core_autofree.hpp>
 #include <srs_rtmp_stack.hpp>
+#include <srs_app_utility.hpp>
 
 #include <srtp2/srtp.h>
 #include <openssl/ssl.h>
@@ -414,10 +415,16 @@ srs_error_t SrsDtls::do_handshake()
         }   
     }   
 
-    if (out_bio_len) {
+    if (out_bio_len <= 0) {
-        if ((err = callback->write_dtls_data(out_bio_data, out_bio_len)) != srs_success) {
+        return err;
-            return srs_error_wrap(err, "dtls send size=%u", out_bio_len);
+    }
-        }
+
+    // Trace the detail of DTLS packet.
+    trace((char*)out_bio_data, out_bio_len, false);
+
+    if ((err = callback->write_dtls_data(out_bio_data, out_bio_len)) != srs_success) {
+        return srs_error_wrap(err, "dtls send size=%u, data=[%s]", out_bio_len,
+            srs_string_dumps_hex((char*)out_bio_data, out_bio_len, 32).c_str());
     }
 
     return err;
@@ -426,16 +433,33 @@ srs_error_t SrsDtls::do_handshake()
 srs_error_t SrsDtls::on_dtls(char* data, int nb_data)
 {
     srs_error_t err = srs_success;
-    if (BIO_reset(bio_in) != 1) {
+
-        return srs_error_new(ERROR_OpenSslBIOReset, "BIO_reset");
+    if ((err = do_on_dtls(data, nb_data)) != srs_success) {
-    }
+        return srs_error_wrap(err, "on_dtls size=%u, data=[%s]", nb_data,
-    if (BIO_reset(bio_out) != 1) {
+            srs_string_dumps_hex(data, nb_data, 32).c_str());
-        return srs_error_new(ERROR_OpenSslBIOReset, "BIO_reset");
     }
 
-    if (BIO_write(bio_in, data, nb_data) <= 0) {
+    return err;
+}
+
+srs_error_t SrsDtls::do_on_dtls(char* data, int nb_data)
+{
+    srs_error_t err = srs_success;
+
+    int r0 = 0;
+    if ((r0 = BIO_reset(bio_in)) != 1) {
+        return srs_error_new(ERROR_OpenSslBIOReset, "BIO_reset r0=%d", r0);
+    }
+    if ((r0 = BIO_reset(bio_out)) != 1) {
+        return srs_error_new(ERROR_OpenSslBIOReset, "BIO_reset r0=%d", r0);
+    }
+
+    // Trace the detail of DTLS packet.
+    trace((char*)data, nb_data, true);
+
+    if ((r0 = BIO_write(bio_in, data, nb_data)) <= 0) {
         // TODO: 0 or -1 maybe block, use BIO_should_retry to check.
-        return srs_error_new(ERROR_OpenSslBIOWrite, "BIO_write");
+        return srs_error_new(ERROR_OpenSslBIOWrite, "BIO_write r0=%d", r0);
     }
 
     if (!handshake_done) {
@@ -444,10 +468,11 @@ srs_error_t SrsDtls::on_dtls(char* data, int nb_data)
         while (BIO_ctrl_pending(bio_in) > 0) {
             char dtls_read_buf[8092];
             int nb = SSL_read(dtls, dtls_read_buf, sizeof(dtls_read_buf));
-
+            
-            if (nb > 0 && callback) {
+            if (callback && nb > 0) {
                 if ((err = callback->on_dtls_application_data(dtls_read_buf, nb)) != srs_success) {
-                    return srs_error_wrap(err, "on DTLS data, size=%u", nb);
+                    return srs_error_wrap(err, "on DTLS data, size=%u, data=[%s]", nb,
+                        srs_string_dumps_hex(dtls_read_buf, nb, 32).c_str());
                 }
             }
         }
@@ -456,6 +481,13 @@ srs_error_t SrsDtls::on_dtls(char* data, int nb_data)
     return err;
 }
 
+void SrsDtls::trace(char* data, int size, bool incoming)
+{
+    // change_cipher_spec(20), alert(21), handshake(22), application_data(23)
+    // @see https://tools.ietf.org/html/rfc2246#section-6.2.1
+    srs_trace("DTLS: %s size=%u", (incoming? "RECV":"SEND"), size);
+}
+
 srs_error_t SrsDtls::start_active_handshake()
 {
     if (role_ == SrsDtlsRoleClient) {

trunk/src/app/srs_app_rtc_dtls.hpp

@@ -117,6 +117,10 @@ public:
     // When got DTLS packet, may handshake packets or application data.
     // @remark When we are passive(DTLS server), we start handshake when got DTLS packet.
     srs_error_t on_dtls(char* data, int nb_data);
+private:
+    srs_error_t do_on_dtls(char* data, int nb_data);
+    void trace(char* data, int size, bool incoming);
+public:
     srs_error_t get_srtp_key(std::string& recv_key, std::string& send_key);
 private:
     SSL_CTX* build_dtls_ctx();