--- res_rtp_asterisk.c.orig 2015-02-25 14:47:25.772839327 +0100 +++ res/res_rtp_asterisk.c 2015-02-27 21:20:54.736498095 +0100 @@ -204,6 +204,10 @@ #ifdef HAVE_OPENSSL_SRTP struct dtls_details { + ast_mutex_t lock ; /*!< SSL mutex */ + /*ast_mutex_t master_pending_lock ;*/ /*!< SSL pending mutex */ + /*ast_mutex_t dtls_timer_lock; */ /*!< Lock for synchronization purposes */ + int dtlstimerid; /*!< Scheduled item id for DTLS retransmission for RTP */ SSL *ssl; /*!< SSL session */ BIO *read_bio; /*!< Memory buffer for reading */ BIO *write_bio; /*!< Memory buffer for writing */ @@ -1202,6 +1206,11 @@ enum ast_rtp_dtls_setup setup) { dtls->dtls_setup = setup; + ast_mutex_init(&dtls->lock); + + + ast_log(LOG_ERROR, "stefandebug dtls details initialize ctx %p ssl_ctx and dtls %p \n", ssl_ctx, dtls); + if (!(dtls->ssl = SSL_new(ssl_ctx))) { ast_log(LOG_ERROR, "Failed to allocate memory for SSL\n"); @@ -1219,13 +1228,15 @@ goto error; } BIO_set_mem_eof_return(dtls->write_bio, -1); - + ast_log(LOG_ERROR, "stefandebug setting bio %p an %p and %p \n",dtls->ssl, dtls->read_bio, dtls->write_bio); SSL_set_bio(dtls->ssl, dtls->read_bio, dtls->write_bio); if (dtls->dtls_setup == AST_RTP_DTLS_SETUP_PASSIVE) { + ast_log(LOG_ERROR, "stefandebug setting accept_state passive %p \n",dtls->ssl); SSL_set_accept_state(dtls->ssl); } else { SSL_set_connect_state(dtls->ssl); + ast_log(LOG_ERROR, "stefandebug setting connect_state %p \n",dtls->ssl); } dtls->connection = AST_RTP_DTLS_CONNECTION_NEW; @@ -1265,6 +1276,7 @@ struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); int res; + ast_log(LOG_ERROR, "trying to set dtls conf on %p \n",instance); if (!dtls_cfg->enabled) { return 0; } @@ -1392,6 +1404,7 @@ static void ast_rtp_dtls_stop(struct ast_rtp_instance *instance) { + ast_log(LOG_ERROR, "stefandebug stopping dtls on rtp %p \n",instance); struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); if (rtp->ssl_ctx) { @@ -1412,14 +1425,17 @@ static void ast_rtp_dtls_reset(struct ast_rtp_instance *instance) { + ast_log(LOG_ERROR, "stefandebug resetting dtls on rtp isntance %p \n",instance); struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); if (SSL_is_init_finished(rtp->dtls.ssl)) { + ast_log(LOG_ERROR, "stefandebug calling ssl shutdown on %p \n",rtp->dtls.ssl); SSL_shutdown(rtp->dtls.ssl); rtp->dtls.connection = AST_RTP_DTLS_CONNECTION_NEW; } if (rtp->rtcp && SSL_is_init_finished(rtp->rtcp->dtls.ssl)) { + ast_log(LOG_ERROR, "stefandebug calling ssl shutdown on %p \n",rtp->rtcp->dtls.ssl); SSL_shutdown(rtp->rtcp->dtls.ssl); rtp->rtcp->dtls.connection = AST_RTP_DTLS_CONNECTION_NEW; } @@ -1475,9 +1491,13 @@ } if (*dtls_setup == AST_RTP_DTLS_SETUP_ACTIVE) { + ast_log(LOG_ERROR, "setting connect state on %p \n",ssl); SSL_set_connect_state(ssl); + ast_log(LOG_ERROR, "setting connect state FINISHED on %p \n",ssl); } else if (*dtls_setup == AST_RTP_DTLS_SETUP_PASSIVE) { + ast_log(LOG_ERROR, "setting passive state on %p \n",ssl); SSL_set_accept_state(ssl); + ast_log(LOG_ERROR, "setting passive state FINISHED on %p \n",ssl); } else { return; } @@ -1581,6 +1601,7 @@ #ifdef HAVE_OPENSSL_SRTP static void dtls_perform_handshake(struct ast_rtp_instance *instance, struct dtls_details *dtls, int rtcp) { + ast_log(LOG_ERROR, "dtls perform handshake called on rtp, dtls, rtcp?: %p , %p, %d\n",instance,dtls,rtcp); struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); if (!dtls->ssl) { @@ -1588,6 +1609,7 @@ } if (SSL_is_init_finished(dtls->ssl)) { + ast_log(LOG_ERROR, "calling clear on DTLS->ssl, %p , %p, %p \n",instance,dtls,dtls->ssl); SSL_clear(dtls->ssl); if (dtls->dtls_setup == AST_RTP_DTLS_SETUP_PASSIVE) { SSL_set_accept_state(dtls->ssl); @@ -1596,8 +1618,18 @@ } dtls->connection = AST_RTP_DTLS_CONNECTION_NEW; } - SSL_do_handshake(dtls->ssl); + /* test */ + if (dtls->dtls_setup != AST_RTP_DTLS_SETUP_PASSIVE) { + SSL_do_handshake(dtls->ssl); + ast_log(LOG_ERROR, "stefandebug SSL_do_handshake finished, %p , %p, %p \n",instance,dtls,dtls->ssl); + } else { + ast_log(LOG_ERROR, "stefandebug no handshake at all called, we are passive??, %p , %p, %p \n",instance,dtls,dtls->ssl); + } + + + ast_mutex_lock(&dtls->lock); dtls_srtp_check_pending(instance, rtp, rtcp); + ast_mutex_unlock(&dtls->lock); } #endif @@ -1609,6 +1641,24 @@ struct ast_rtp_instance *instance = ice->user_data; struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); + + +#ifdef HAVE_OPENSSL_SRTP + //for debug: + + int count=0; + while (( (rtp->dtls.dtls_setup == AST_RTP_DTLS_SETUP_ACTPASS) || (rtp->rtcp && rtp->rtcp->dtls.dtls_setup == AST_RTP_DTLS_SETUP_ACTPASS) ) && count < 30) { + ast_log(LOG_ERROR, "UNEXPECTED loop %d on ice complete for dtls \n",count,&rtp->dtls); + /*give chan_sip at least 3 seconds to do dtls_setup */ + usleep(100000); + count++; + if (count==30) { + return; + } + } + + +#endif if (status == PJ_SUCCESS) { struct ast_sockaddr remote_address; @@ -1622,12 +1672,21 @@ update_address_with_ice_candidate(rtp, AST_RTP_ICE_COMPONENT_RTCP, &rtp->rtcp->them); } } + + #ifdef HAVE_OPENSSL_SRTP + + + ast_mutex_lock(&rtp->dtls.lock); + ast_log(LOG_ERROR, "calling dtls perform handshake \n"); dtls_perform_handshake(instance, &rtp->dtls, 0); + ast_mutex_unlock(&rtp->dtls.lock); if (rtp->rtcp) { + ast_mutex_lock(&rtp->rtcp->dtls.lock); dtls_perform_handshake(instance, &rtp->rtcp->dtls, 1); + ast_mutex_unlock(&rtp->rtcp->dtls.lock); } #endif @@ -1755,6 +1814,7 @@ static int dtls_srtp_handle_timeout(const void *data) { struct ast_rtp_instance *instance = (struct ast_rtp_instance *)data; + ast_log(LOG_ERROR, "dtls_srtp_handle_timeout called, instance: %p \n",instance); struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); if (!rtp) @@ -1775,14 +1835,22 @@ if (rtp->dtls.ssl && !SSL_is_init_finished(rtp->dtls.ssl)) { DTLSv1_handle_timeout(rtp->dtls.ssl); + ast_log(LOG_ERROR, " DTLSv1_handle_timeout FINISHED on RTP, rtp instance,%p , dtls: %p, dtls->ssl: %p \n",instance, rtp->dtls, rtp->dtls.ssl); } + ast_mutex_lock(&rtp->dtls.lock); dtls_srtp_check_pending(instance, rtp, 0); + ast_mutex_unlock(&rtp->dtls.lock); if (rtp->rtcp && rtp->rtcp->dtls.ssl && !SSL_is_init_finished(rtp->rtcp->dtls.ssl)) { DTLSv1_handle_timeout(rtp->rtcp->dtls.ssl); + ast_log(LOG_ERROR, " DTLSv1_handle_timeout FINISHED on RTCP, rtp instance,%p , dtls: %p, dtls->ssl: %p \n",instance, rtp->rtcp->dtls, rtp->rtcp->dtls.ssl); } - dtls_srtp_check_pending(instance, rtp, 1); + if (rtp->rtcp && rtp->rtcp->dtls.ssl) { + ast_mutex_lock(&rtp->rtcp->dtls.lock); + dtls_srtp_check_pending(instance, rtp, 1); + ast_mutex_unlock(&rtp->rtcp->dtls.lock); + } ao2_ref(instance, -1); return 0; @@ -1798,8 +1866,13 @@ return; } + ast_log(LOG_ERROR, "dtls_srtp_check_pending called dtls, rtcp?: %p, %d\n",dtls, rtcp); + + pending = BIO_ctrl_pending(dtls->write_bio); + ast_log(LOG_ERROR, "BIO_ctrl_pending returned %d, dtls, rtcp?: %p, %d\n",pending,dtls, rtcp); + if (pending > 0) { char outgoing[pending]; size_t out; @@ -1816,12 +1889,14 @@ if (ast_sockaddr_isnull(&remote_address)) { return; } - + ast_log(LOG_ERROR, "doing bio read in srtp check pending, %p, %d\n",dtls,rtcp); out = BIO_read(dtls->write_bio, outgoing, sizeof(outgoing)); + ast_log(LOG_ERROR, "bio read return value, %d\n",out); /* Stop existing DTLS timer if running */ ast_mutex_lock(&rtp->dtls_timer_lock); if (rtp->dtlstimerid > -1) { + ast_log(LOG_ERROR, "scheduling delete of old dtls timer,dtls,rtcp %p, %d\n",dtls,rtcp); AST_SCHED_DEL_UNREF(rtp->sched, rtp->dtlstimerid, ao2_ref(instance, -1)); rtp->dtlstimerid = -1; } @@ -1829,10 +1904,12 @@ if (DTLSv1_get_timeout(dtls->ssl, &dtls_timeout)) { int timeout = dtls_timeout.tv_sec * 1000 + dtls_timeout.tv_usec / 1000; ao2_ref(instance, +1); + ast_log(LOG_ERROR, "creating a new timer timeout: %d, %p, %d\n",timeout,dtls,rtcp); if ((rtp->dtlstimerid = ast_sched_add(rtp->sched, timeout, dtls_srtp_handle_timeout, instance)) < 0) { ao2_ref(instance, -1); ast_log(LOG_WARNING, "scheduling DTLS retransmission for RTP instance [%p] failed.\n", instance); } + ast_log(LOG_ERROR, "created timer: %d, %p, %d\n",rtp->dtlstimerid,dtls,rtcp); } ast_mutex_unlock(&rtp->dtls_timer_lock); @@ -1842,6 +1919,7 @@ static int dtls_srtp_renegotiate(const void *data) { + ast_log(LOG_ERROR, "SHOULD NEVER BE CALLED!!!! SRTP RENEOGITATE \n"); struct ast_rtp_instance *instance = (struct ast_rtp_instance *)data; struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); @@ -2009,11 +2087,16 @@ } #ifdef HAVE_OPENSSL_SRTP - dtls_srtp_check_pending(instance, rtp, rtcp); + + /* ast_mutex_lock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ + dtls_srtp_check_pending(instance, rtp, rtcp); + /* ast_mutex_unlock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ /* If this is an SSL packet pass it to OpenSSL for processing */ if ((*in >= 20) && (*in <= 64)) { + struct dtls_details *dtls = !rtcp ? &rtp->dtls : &rtp->rtcp->dtls; + ast_log(LOG_ERROR, "We received an ssl packet rtp,'%p', dtls, %p\n",instance,dtls); int res = 0; /* If no SSL session actually exists terminate things */ @@ -2026,14 +2109,23 @@ /* If we don't yet know if we are active or passive and we receive a packet... we are obviously passive */ if (dtls->dtls_setup == AST_RTP_DTLS_SETUP_ACTPASS) { dtls->dtls_setup = AST_RTP_DTLS_SETUP_PASSIVE; + ast_log(LOG_ERROR, "Setting passive from actpass in rtp_rcvfrom '%p', dtls, %p\n",instance,dtls); SSL_set_accept_state(dtls->ssl); } - dtls_srtp_check_pending(instance, rtp, rtcp); - BIO_write(dtls->read_bio, buf, len); + /* ast_mutex_lock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ + dtls_srtp_check_pending(instance, rtp, rtcp); + /* ast_mutex_unlock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ + ast_mutex_lock(&dtls->lock); + ast_log(LOG_ERROR, "Writing buf len %d to dtls->read_bio ,'%p', dtls, %p\n",len,instance,dtls); + BIO_write(dtls->read_bio, buf, len); + + /*why do this? */ len = SSL_read(dtls->ssl, buf, len); + ast_mutex_unlock(&dtls->lock); + ast_log(LOG_ERROR, "Finished reading, len %d,'%p', dtls, %p\n",len,instance,dtls); if ((len < 0) && (SSL_get_error(dtls->ssl, len) == SSL_ERROR_SSL)) { unsigned long error = ERR_get_error(); @@ -2042,13 +2134,17 @@ return -1; } - dtls_srtp_check_pending(instance, rtp, rtcp); + + /* ast_mutex_lock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ + dtls_srtp_check_pending(instance, rtp, rtcp); + /* ast_mutex_unlock(rtcp ? &rtp->rtcp->dtls.lock : &rtp->dtls.lock); */ if (SSL_is_init_finished(dtls->ssl)) { /* Any further connections will be existing since this is now established */ dtls->connection = AST_RTP_DTLS_CONNECTION_EXISTING; if (!rtcp) { /* Use the keying material to set up key/salt information */ + ast_log(LOG_ERROR, "calling dtls_srtp_stup from rtp_rcvfrom because init is finished on rtp->dtls->ssl,'%p', dtls, %p\n",instance,dtls); res = dtls_srtp_setup(rtp, srtp, instance); } } @@ -2485,7 +2581,9 @@ static int ast_rtp_destroy(struct ast_rtp_instance *instance) { + struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); + ast_log(LOG_ERROR, "stefandebug DESTROYING RTP INSTANCE %p \n", instance); #ifdef HAVE_PJPROJECT struct timeval wait = ast_tvadd(ast_tvnow(), ast_samp2tv(TURN_STATE_WAIT_TIME, 1000)); struct timespec ts = { .tv_sec = wait.tv_sec, .tv_nsec = wait.tv_usec * 1000, }; @@ -2511,8 +2609,12 @@ close(rtp->rtcp->s); #ifdef HAVE_OPENSSL_SRTP if (rtp->rtcp->dtls.ssl) { - SSL_free(rtp->rtcp->dtls.ssl); + ast_log(LOG_ERROR, "RTCP about to do SSL_free from ast_rtp_destroy on %p\n", &rtp->rtcp->dtls); + ast_mutex_lock(&rtp->rtcp->dtls.lock); + SSL_free(rtp->rtcp->dtls.ssl); + ast_mutex_unlock(&rtp->rtcp->dtls.lock); } + ast_mutex_destroy(&rtp->rtcp->dtls.lock); #endif ast_free(rtp->rtcp); } @@ -2567,6 +2669,10 @@ #ifdef HAVE_OPENSSL_SRTP /* Destroy the SSL context if present */ + ast_log(LOG_ERROR, "RTP destroy. about to do SSL_free from ast_rtp_destroy on %p \n", &rtp->dtls); + ast_mutex_lock(&rtp->dtls.lock); + + if (rtp->ssl_ctx) { SSL_CTX_free(rtp->ssl_ctx); } @@ -2575,6 +2681,9 @@ if (rtp->dtls.ssl) { SSL_free(rtp->dtls.ssl); } + + ast_mutex_unlock(&rtp->dtls.lock); + #endif ao2_cleanup(rtp->lasttxformat); @@ -2583,6 +2692,7 @@ /* Destroy synchronization items */ ast_mutex_destroy(&rtp->lock); + ast_mutex_destroy(&rtp->dtls.lock); ast_cond_destroy(&rtp->cond); /* Finally destroy ourselves */ @@ -4689,7 +4799,9 @@ return; } else { + if (rtp->rtcp) { + ast_log(LOG_ERROR, "RTCP about to destroy rtp->rtcp for rtp instance %p\n", instance); if (rtp->rtcp->schedid > 0) { if (!ast_sched_del(rtp->sched, rtp->rtcp->schedid)) { /* Successfully cancelled scheduler entry. */ @@ -4704,7 +4816,10 @@ close(rtp->rtcp->s); #ifdef HAVE_OPENSSL_SRTP if (rtp->rtcp->dtls.ssl) { + ast_log(LOG_ERROR, "RTCP about to do SSL_free on %p\n", &rtp->rtcp->dtls); + ast_mutex_lock(&rtp->rtcp->dtls.lock); SSL_free(rtp->rtcp->dtls.ssl); + ast_mutex_unlock(&rtp->rtcp->dtls.lock); } #endif ast_free(rtp->rtcp); @@ -4989,7 +5104,7 @@ struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); /* If ICE negotiation is enabled the DTLS Handshake will be performed upon completion of it */ -#ifdef USE_PJPROJECT +#ifdef HAVE_PJPROJECT if (rtp->ice) { return 0; }