morgan/UxPlay
1
0
Fork 0
mirror of https://github.com/morgan9e/UxPlay synced 2026-04-14 00:04:13 +09:00
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #193 from FDH2/testing

Browse Source 
only call utils_data_to_string in -d debug mode
This commit is contained in:
fduncanh
2023-04-18 03:45:53 -04:00
committed by GitHub
parent 653158eabb 3dfdf42fad
commit 803217ce7d
7 changed files with 122 additions and 70 deletions
Download Patch File Download Diff File Expand all files Collapse all files

16
lib/logger.c
View File

@@ -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 <stdlib.h>
@@ -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)
{

4
lib/logger.h
View File

@@ -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, ...);

8
lib/raop.c
View File

@@ -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);

45
lib/raop_handlers.h
View File

@@ -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

24
lib/raop_ntp.c
View File

@@ -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.

43
lib/raop_rtp.c
View File

@@ -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 */

52
lib/raop_rtp_mirror.c
View File

@@ -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;