From 3dfdf42fadc0fd2c2471300df89c54dcf3177864 Mon Sep 17 00:00:00 2001 From: "F. Duncanh" Date: Mon, 17 Apr 2023 20:59:29 -0400 Subject: [PATCH] only call utils_data_to_string in -d debug mode --- lib/logger.c | 16 +++++++++++++ lib/logger.h | 4 ++++ lib/raop.c | 8 +++---- lib/raop_handlers.h | 45 ++++++++++++++++++++++--------------- lib/raop_ntp.c | 24 ++++++++++++-------- lib/raop_rtp.c | 43 +++++++++++++++++++++-------------- lib/raop_rtp_mirror.c | 52 +++++++++++++++++++++++++------------------ 7 files changed, 122 insertions(+), 70 deletions(-) diff --git a/lib/logger.c b/lib/logger.c index f3fe354..fb3f560 100644 --- a/lib/logger.c +++ b/lib/logger.c @@ -10,6 +10,9 @@ * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU * Lesser General Public License for more details. + * + *=============================================================== + * modified by fduncanh 2023 */ #include @@ -61,6 +64,19 @@ logger_set_level(logger_t *logger, int level) MUTEX_UNLOCK(logger->lvl_mutex); } +int +logger_get_level(logger_t *logger) +{ + int level; + assert(logger); + + MUTEX_LOCK(logger->lvl_mutex); + level = logger->level; + MUTEX_UNLOCK(logger->lvl_mutex); + + return level; +} + void logger_set_callback(logger_t *logger, logger_callback_t callback, void *cls) { diff --git a/lib/logger.h b/lib/logger.h index 00a4257..970344f 100644 --- a/lib/logger.h +++ b/lib/logger.h @@ -10,6 +10,9 @@ * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU * Lesser General Public License for more details. + * + *================================================================= + * modified by fduncanh 2023 */ #ifndef LOGGER_H @@ -37,6 +40,7 @@ logger_t *logger_init(); void logger_destroy(logger_t *logger); void logger_set_level(logger_t *logger, int level); +int logger_get_level(logger_t *logger); void logger_set_callback(logger_t *logger, logger_callback_t callback, void *cls); void logger_log(logger_t *logger, int level, const char *fmt, ...); diff --git a/lib/raop.c b/lib/raop.c index 7c63e69..a88f1eb 100644 --- a/lib/raop.c +++ b/lib/raop.c @@ -156,13 +156,13 @@ conn_init(void *opaque, unsigned char *local, int locallen, unsigned char *remot static void conn_request(void *ptr, http_request_t *request, http_response_t **response) { raop_conn_t *conn = ptr; - logger_log(conn->raop->logger, LOGGER_DEBUG, "conn_request"); const char *method; const char *url; const char *cseq; - char *response_data = NULL; int response_datalen = 0; + logger_log(conn->raop->logger, LOGGER_DEBUG, "conn_request"); + bool logger_debug = (logger_get_level(conn->raop->logger) >= LOGGER_DEBUG); method = http_request_get_method(request); url = http_request_get_url(request); @@ -180,7 +180,7 @@ conn_request(void *ptr, http_request_t *request, http_response_t **response) { free(header_str); int request_datalen; const char *request_data = http_request_get_data(request, &request_datalen); - if (request_data) { + if (request_data && logger_debug) { if (request_datalen > 0) { if (data_is_plist) { plist_t req_root_node = NULL; @@ -333,7 +333,7 @@ conn_request(void *ptr, http_request_t *request, http_response_t **response) { bool data_is_text = (strstr(header_str,"text/parameters") != NULL); free(header_str); if (response_data) { - if (response_datalen > 0) { + if (response_datalen > 0 && logger_debug) { if (data_is_plist) { plist_t res_root_node = NULL; plist_from_bin(response_data, response_datalen, &res_root_node); diff --git a/lib/raop_handlers.h b/lib/raop_handlers.h index b8554ac..48af4d1 100644 --- a/lib/raop_handlers.h +++ b/lib/raop_handlers.h @@ -318,10 +318,10 @@ raop_handler_setup(raop_conn_t *conn, int use_udp; const char *dacp_id; const char *active_remote_header; - + bool logger_debug = (logger_get_level(conn->raop->logger) >= LOGGER_DEBUG); + const char *data; int data_len; - data = http_request_get_data(request, &data_len); dacp_id = http_request_get_header(request, "DACP-ID"); @@ -369,9 +369,11 @@ raop_handler_setup(raop_conn_t *conn, memcpy(aesiv, eiv, 16); free(eiv); logger_log(conn->raop->logger, LOGGER_DEBUG, "eiv_len = %llu", eiv_len); - char* str = utils_data_to_string(aesiv, 16, 16); - logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aesiv (needed for AES-CBC audio decryption iv):\n%s", str); - free(str); + if (logger_debug) { + char* str = utils_data_to_string(aesiv, 16, 16); + logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aesiv (needed for AES-CBC audio decryption iv):\n%s", str); + free(str); + } char* ekey = NULL; uint64_t ekey_len = 0; @@ -380,21 +382,26 @@ raop_handler_setup(raop_conn_t *conn, free(ekey); logger_log(conn->raop->logger, LOGGER_DEBUG, "ekey_len = %llu", ekey_len); // eaeskey is 72 bytes, aeskey is 16 bytes - str = utils_data_to_string((unsigned char *) eaeskey, ekey_len, 16); - logger_log(conn->raop->logger, LOGGER_DEBUG, "ekey:\n%s", str); - free (str); - + if (logger_debug) { + char *str = utils_data_to_string((unsigned char *) eaeskey, ekey_len, 16); + logger_log(conn->raop->logger, LOGGER_DEBUG, "ekey:\n%s", str); + free (str); + } int ret = fairplay_decrypt(conn->fairplay, (unsigned char*) eaeskey, aeskey); logger_log(conn->raop->logger, LOGGER_DEBUG, "fairplay_decrypt ret = %d", ret); - str = utils_data_to_string(aeskey, 16, 16); - logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aeskey (fairplay-decrypted from ekey):\n%s", str); - free(str); + if (logger_debug) { + char *str = utils_data_to_string(aeskey, 16, 16); + logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aeskey (fairplay-decrypted from ekey):\n%s", str); + free(str); + } unsigned char ecdh_secret[X25519_KEY_SIZE]; pairing_get_ecdh_secret_key(conn->pairing, ecdh_secret); - str = utils_data_to_string(ecdh_secret, X25519_KEY_SIZE, 16); - logger_log(conn->raop->logger, LOGGER_DEBUG, "32 byte shared ecdh_secret:\n%s", str); - free(str); + if (logger_debug) { + char *str = utils_data_to_string(ecdh_secret, X25519_KEY_SIZE, 16); + logger_log(conn->raop->logger, LOGGER_DEBUG, "32 byte shared ecdh_secret:\n%s", str); + free(str); + } const char *user_agent = http_request_get_header(request, "User-Agent"); logger_log(conn->raop->logger, LOGGER_INFO, "Client identified as User-Agent: %s", user_agent); @@ -413,9 +420,11 @@ raop_handler_setup(raop_conn_t *conn, sha_final(ctx, eaeskey, NULL); sha_destroy(ctx); memcpy(aeskey, eaeskey, 16); - str = utils_data_to_string(aeskey, 16, 16); - logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aeskey after sha-256 hash with ecdh_secret:\n%s", str); - free(str); + if (logger_debug) { + char *str = utils_data_to_string(aeskey, 16, 16); + logger_log(conn->raop->logger, LOGGER_DEBUG, "16 byte aeskey after sha-256 hash with ecdh_secret:\n%s", str); + free(str); + } } // Time port diff --git a/lib/raop_ntp.c b/lib/raop_ntp.c index ce0ad34..0431506 100644 --- a/lib/raop_ntp.c +++ b/lib/raop_ntp.c @@ -272,6 +272,7 @@ raop_ntp_thread(void *arg) const unsigned two_pow_n[RAOP_NTP_DATA_COUNT] = {2, 4, 8, 16, 32, 64, 128, 256}; int timeout_counter = 0; bool conn_reset = false; + bool logger_debug = (logger_get_level(raop_ntp->logger) >= LOGGER_DEBUG); while (1) { MUTEX_LOCK(raop_ntp->run_mutex); @@ -289,10 +290,12 @@ raop_ntp_thread(void *arg) byteutils_put_ntp_timestamp(request, 24, send_time); int send_len = sendto(raop_ntp->tsock, (char *)request, sizeof(request), 0, (struct sockaddr *) &raop_ntp->remote_saddr, raop_ntp->remote_saddr_len); - char *str = utils_data_to_string(request, send_len, 16); - logger_log(raop_ntp->logger, LOGGER_DEBUG, "\nraop_ntp send time type_t=%d send_len = %d, now = %8.6f\n%s", - request[1] &~0x80, send_len, (double) send_time / SECOND_IN_NSECS, str); - free(str); + if (logger_debug) { + char *str = utils_data_to_string(request, send_len, 16); + logger_log(raop_ntp->logger, LOGGER_DEBUG, "\nraop_ntp send time type_t=%d send_len = %d, now = %8.6f\n%s", + request[1] &~0x80, send_len, (double) send_time / SECOND_IN_NSECS, str); + free(str); + } if (send_len < 0) { logger_log(raop_ntp->logger, LOGGER_ERR, "raop_ntp error sending request"); } else { @@ -324,11 +327,14 @@ raop_ntp_thread(void *arg) // Local time of the client when the response message leaves the client int64_t t2 = (int64_t) byteutils_get_ntp_timestamp(response, 24); - char *str = utils_data_to_string(response, response_len, 16); - logger_log(raop_ntp->logger, LOGGER_DEBUG, "raop_ntp receive time type_t=%d packetlen = %d, now = %8.6f t1 = %8.6f, t2 = %8.6f\n%s", - response[1] &~0x80, response_len, (double) t3 / SECOND_IN_NSECS, (double) t1 / SECOND_IN_NSECS, (double) t2 / SECOND_IN_NSECS, str); - free(str); - + if (logger_debug) { + char *str = utils_data_to_string(response, response_len, 16); + logger_log(raop_ntp->logger, LOGGER_DEBUG, + "raop_ntp receive time type_t=%d packetlen = %d, now = %8.6f t1 = %8.6f, t2 = %8.6f\n%s", + response[1] &~0x80, response_len, (double) t3 / SECOND_IN_NSECS, (double) t1 / SECOND_IN_NSECS, + (double) t2 / SECOND_IN_NSECS, str); + free(str); + } // The iOS client device sends its time in seconds relative to an arbitrary Epoch (the last boot). // For a little bonus confusion, they add SECONDS_FROM_1900_TO_1970. // This means we have to expect some rather huge offset, but its growth or shrink over time should be small. diff --git a/lib/raop_rtp.c b/lib/raop_rtp.c index dadb905..f8284b2 100644 --- a/lib/raop_rtp.c +++ b/lib/raop_rtp.c @@ -463,6 +463,7 @@ raop_rtp_thread_udp(void *arg) unsigned short seqnum1 = 0, seqnum2 = 0; assert(raop_rtp); + bool logger_debug = (logger_get_level(raop_rtp->logger) >= LOGGER_DEBUG); raop_rtp->ntp_start_time = raop_ntp_get_local_time(raop_rtp->ntp); raop_rtp->rtp_clock_started = false; for (int i = 0; i < RAOP_RTP_SYNC_DATA_COUNT; i++) { @@ -531,7 +532,7 @@ raop_rtp_thread_udp(void *arg) logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp resent audio packet: seqnum=%u", seqnum); int result = raop_buffer_enqueue(raop_rtp->buffer, resent_packet, resent_packetlen, &ntp_time, &rtp_time, 1); assert(result >= 0); - } else { + } else if (logger_debug) { /* type_c = 0x56 packets with length 8 have been reported */ char *str = utils_data_to_string(packet, packetlen, 16); logger_log(raop_rtp->logger, LOGGER_DEBUG, "Received empty resent audio packet length %d, seqnum=%u:\n%s", @@ -557,15 +558,17 @@ raop_rtp_thread_udp(void *arg) } uint64_t sync_ntp_raw = byteutils_get_long_be(packet, 8); uint64_t sync_ntp_remote = raop_ntp_timestamp_to_nano_seconds(sync_ntp_raw, true); - uint64_t sync_ntp_local = raop_ntp_convert_remote_time(raop_rtp->ntp, sync_ntp_remote); - char *str = utils_data_to_string(packet, packetlen, 20); - logger_log(raop_rtp->logger, LOGGER_DEBUG, - "raop_rtp sync: client ntp=%8.6f, ntp = %8.6f, ntp_start_time %8.6f\nts_client = %8.6f sync_rtp=%u\n%s", - (double) sync_ntp_remote / SEC, (double) sync_ntp_local / SEC, - (double) raop_rtp->ntp_start_time / SEC, (double) sync_ntp_remote / SEC, sync_rtp, str); - free(str); + if (logger_debug) { + uint64_t sync_ntp_local = raop_ntp_convert_remote_time(raop_rtp->ntp, sync_ntp_remote); + char *str = utils_data_to_string(packet, packetlen, 20); + logger_log(raop_rtp->logger, LOGGER_DEBUG, + "raop_rtp sync: client ntp=%8.6f, ntp = %8.6f, ntp_start_time %8.6f\nts_client = %8.6f sync_rtp=%u\n%s", + (double) sync_ntp_remote / SEC, (double) sync_ntp_local / SEC, + (double) raop_rtp->ntp_start_time / SEC, (double) sync_ntp_remote / SEC, sync_rtp, str); + free(str); + } raop_rtp_sync_clock(raop_rtp, &sync_ntp_remote, &sync_rtp64); - } else { + } else if (logger_debug) { char *str = utils_data_to_string(packet, packetlen, 16); logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp unknown udp control packet\n%s", str); free(str); @@ -619,9 +622,12 @@ raop_rtp_thread_udp(void *arg) //logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp_thread_udp type_d 0x%02x, packetlen = %d", type_d, packetlen); if (packetlen < 12) { - char *str = utils_data_to_string(packet, packetlen, 16); - logger_log(raop_rtp->logger, LOGGER_DEBUG, "Received short type_d = 0x%2x packet with length %d:\n%s", packet[1] & ~0x80, packetlen, str); - free (str); + if (logger_debug) { + char *str = utils_data_to_string(packet, packetlen, 16); + logger_log(raop_rtp->logger, LOGGER_DEBUG, "Received short type_d = 0x%2x packet with length %d:\n%s", + packet[1] & ~0x80, packetlen, str); + free (str); + } continue; } @@ -694,11 +700,14 @@ raop_rtp_thread_udp(void *arg) } raop_rtp->callbacks.audio_process(raop_rtp->callbacks.cls, raop_rtp->ntp, &audio_data); free(payload); - uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp->ntp); - int64_t latency = ((int64_t) ntp_now) - ((int64_t) audio_data.ntp_time_local); - logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp audio: now = %8.6f, ntp = %8.6f, latency = %8.6f, rtp_time=%u seqnum = %u", - (double) ntp_now / SEC, (double) audio_data.ntp_time_local / SEC, (double) latency / SEC, (uint32_t) rtp64_timestamp, - seqnum); + if (logger_debug) { + uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp->ntp); + int64_t latency = ((int64_t) ntp_now) - ((int64_t) audio_data.ntp_time_local); + logger_log(raop_rtp->logger, LOGGER_DEBUG, + "raop_rtp audio: now = %8.6f, ntp = %8.6f, latency = %8.6f, rtp_time=%u seqnum = %u", + (double) ntp_now / SEC, (double) audio_data.ntp_time_local / SEC, (double) latency / SEC, + (uint32_t) rtp64_timestamp, seqnum); + } } /* Handle possible resend requests */ diff --git a/lib/raop_rtp_mirror.c b/lib/raop_rtp_mirror.c index 06cdaec..0415027 100644 --- a/lib/raop_rtp_mirror.c +++ b/lib/raop_rtp_mirror.c @@ -205,7 +205,7 @@ raop_rtp_mirror_thread(void *arg) uint64_t ntp_timestamp_remote = 0; uint64_t ntp_timestamp_local = 0; unsigned char nal_start_code[4] = { 0x00, 0x00, 0x00, 0x01 }; - + bool logger_debug = (logger_get_level(raop_rtp_mirror->logger) >= LOGGER_DEBUG); #ifdef DUMP_H264 // C decrypted FILE* file = fopen("/home/pi/Airplay.h264", "wb"); @@ -378,10 +378,14 @@ raop_rtp_mirror_thread(void *arg) // counting nano seconds since last boot. ntp_timestamp_local = raop_ntp_convert_remote_time(raop_rtp_mirror->ntp, ntp_timestamp_remote); - uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp_mirror->ntp); - int64_t latency = ((int64_t) ntp_now) - ((int64_t) ntp_timestamp_local); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp video: now = %8.6f, ntp = %8.6f, latency = %8.6f, ts = %8.6f, %s", - (double) ntp_now / SEC, (double) ntp_timestamp_local / SEC, (double) latency / SEC, (double) ntp_timestamp_remote / SEC, packet_description); + if (logger_debug) { + uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp_mirror->ntp); + int64_t latency = ((int64_t) ntp_now) - ((int64_t) ntp_timestamp_local); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, + "raop_rtp video: now = %8.6f, ntp = %8.6f, latency = %8.6f, ts = %8.6f, %s", + (double) ntp_now / SEC, (double) ntp_timestamp_local / SEC, (double) latency / SEC, + (double) ntp_timestamp_remote / SEC, packet_description); + } #ifdef DUMP_H264 fwrite(payload, payload_size, 1, file_source); @@ -498,22 +502,24 @@ raop_rtp_mirror_thread(void *arg) unsigned char *sequence_parameter_set = payload + 8; short pps_size = byteutils_get_short_be(payload, sps_size + 9); unsigned char *picture_parameter_set = payload + sps_size + 11; - int data_size = 6; - char *str = utils_data_to_string(payload, data_size, 16); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror: sps/pps header size = %d", data_size); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 sps/pps header:\n%s", str); - free(str); - str = utils_data_to_string(sequence_parameter_set, sps_size,16); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror sps size = %d", sps_size); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 Sequence Parameter Set:\n%s", str); - free(str); - str = utils_data_to_string(picture_parameter_set, pps_size, 16); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror pps size = %d", pps_size); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 Picture Parameter Set:\n%s", str); - free(str); + int data_size = 6; + if (logger_debug) { + char *str = utils_data_to_string(payload, data_size, 16); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror: sps/pps header size = %d", data_size); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 sps/pps header:\n%s", str); + free(str); + str = utils_data_to_string(sequence_parameter_set, sps_size,16); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror sps size = %d", sps_size); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 Sequence Parameter Set:\n%s", str); + free(str); + str = utils_data_to_string(picture_parameter_set, pps_size, 16); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror pps size = %d", pps_size); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror h264 Picture Parameter Set:\n%s", str); + free(str); + } data_size = payload_size - sps_size - pps_size - 11; - if (data_size > 0) { - str = utils_data_to_string (picture_parameter_set + pps_size, data_size, 16); + if (data_size > 0 && logger_debug) { + char *str = utils_data_to_string (picture_parameter_set + pps_size, data_size, 16); logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "remainder size = %d", data_size); logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "remainder of sps+pps packet:\n%s", str); free(str); @@ -568,9 +574,11 @@ raop_rtp_mirror_thread(void *arg) int plist_size = payload_size; if (payload_size > 25000) { plist_size = payload_size - 25000; - char *str = utils_data_to_string(payload + plist_size, 16, 16); - logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "video_info packet had 25kB trailer; first 16 bytes are:\n%s", str); + if (logger_debug) { + char *str = utils_data_to_string(payload + plist_size, 16, 16); + logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "video_info packet had 25kB trailer; first 16 bytes are:\n%s", str); free(str); + } } if (plist_size) { char *plist_xml;