improved debug output with all messages between client and server

This commit is contained in:
fduncanh
2021-12-12 03:36:40 -05:00
parent 32d57ff271
commit d4b203e48f
4 changed files with 129 additions and 15 deletions

View File

@@ -15,6 +15,7 @@
#include <stdlib.h>
#include <string.h>
#include <assert.h>
#include <stdio.h>
#include "http_request.h"
#include "llhttp/llhttp.h"
@@ -251,3 +252,38 @@ http_request_get_data(http_request_t *request, int *datalen)
}
return request->data;
}
int
http_request_get_header_string(http_request_t *request, char **header_str)
{
if(!request || request->headers_size == 0) {
*header_str = NULL;
return 0;
}
int len = 0;
for (int i = 0; i < request->headers_size; i++) {
len += strlen(request->headers[i]);
if (i%2 == 0) {
len += 2;
} else {
len++;
}
}
char *str = calloc(len+1, sizeof(char));
assert(str);
*header_str = str;
char *p = str;
for (int i = 0; i < request->headers_size; i++) {
sprintf(p,"%s", request->headers[i]);
p += strlen(request->headers[i]);
if (i%2 == 0) {
sprintf(p, ": ");
p +=2;
} else {
sprintf(p, "\n");
p++;
}
}
assert(p == &(str[len]));
return len;
}

View File

@@ -30,6 +30,7 @@ const char *http_request_get_method(http_request_t *request);
const char *http_request_get_url(http_request_t *request);
const char *http_request_get_header(http_request_t *request, const char *name);
const char *http_request_get_data(http_request_t *request, int *datalen);
int http_request_get_header_string(http_request_t *request, char **header_str);
void http_request_destroy(http_request_t *request);

View File

@@ -161,6 +161,38 @@ conn_request(void *ptr, http_request_t *request, http_response_t **response) {
if (!method || !cseq) {
return;
}
logger_log(conn->raop->logger, LOGGER_DEBUG, "\n%s %s RTSP/1.0", method, url);
char *header_str= NULL;
http_request_get_header_string(request, &header_str);
if (header_str) {
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", header_str);
bool data_is_plist = (strstr(header_str,"apple-binary-plist") != NULL);
bool data_is_text = (strstr(header_str,"text/parameters") != NULL);
free(header_str);
int request_datalen;
const char *request_data = http_request_get_data(request, &request_datalen);
if (request_data) {
if (request_datalen > 0) {
if (data_is_plist) {
plist_t req_root_node = NULL;
plist_from_bin(request_data, request_datalen, &req_root_node);
char * plist_xml;
uint32_t plist_len;
plist_to_xml(req_root_node, &plist_xml, &plist_len);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", plist_xml);
free(plist_xml);
} else if (data_is_text) {
char *data_str = utils_data_to_text((char *) request_data, request_datalen);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", data_str);
free(data_str);
} else {
char *data_str = utils_data_to_string((unsigned char *) request_data, request_datalen, 16);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", data_str);
free(data_str);
}
}
}
}
*response = http_response_init("RTSP/1.0", 200, "OK");
@@ -262,8 +294,50 @@ conn_request(void *ptr, http_request_t *request, http_response_t **response) {
if (handler != NULL) {
handler(conn, request, *response, &response_data, &response_datalen);
}
http_response_finish(*response, response_data, response_datalen);
int len;
const char *data = http_response_get_data(*response, &len);
if (response_data && response_datalen > 0) {
len -= response_datalen;
} else {
len -= 2;
}
header_str = (char *) calloc(len+1,sizeof(char));
assert(header_str);
strncpy(header_str, data, len);
char *p = header_str;
while (p) {
p = strchr(p, '\r'); /* replace occurences of '\r' by ' ' */
if (p) *p = ' ';
}
logger_log(conn->raop->logger, LOGGER_DEBUG, "\n%s", header_str);
bool data_is_plist = (strstr(header_str,"apple-binary-plist") != NULL);
bool data_is_text = (strstr(header_str,"text/parameters") != NULL);
free(header_str);
if (response_data) {
if (response_datalen > 0) {
if (data_is_plist) {
plist_t res_root_node = NULL;
plist_from_bin(response_data, response_datalen, &res_root_node);
char * plist_xml;
uint32_t plist_len;
plist_to_xml(res_root_node, &plist_xml, &plist_len);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", plist_xml);
free(plist_xml);
} else if (data_is_text) {
char *data_str = utils_data_to_text((char*) response_data, response_datalen);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", data_str);
free(data_str);
} else {
char *data_str = utils_data_to_string((unsigned char *) response_data, response_datalen, 16);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", data_str);
free(data_str);
}
}
free(response_data);
response_data = NULL;
response_datalen = 0;

View File

@@ -162,12 +162,6 @@ raop_handler_info(raop_conn_t *conn,
plist_to_bin(r_node, response_data, (uint32_t *) response_datalen);
http_response_add_header(response, "Content-Type", "application/x-apple-binary-plist");
logger_log(conn->raop->logger, LOGGER_DEBUG, "UxPlay server info sent in response to client \"GET /info\" request, len = %d:", *response_datalen);
char * plist_xml;
uint32_t plist_len;
plist_to_xml(r_node, &plist_xml, &plist_len);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", plist_xml);
free(plist_xml);
free(pk);
free(hw_addr);
}
@@ -346,11 +340,6 @@ raop_handler_setup(raop_conn_t *conn,
// Parsing bplist
plist_t req_root_node = NULL;
plist_from_bin(data, data_len, &req_root_node);
char * plist_xml;
uint32_t plist_len;
plist_to_xml(req_root_node, &plist_xml, &plist_len);
logger_log(conn->raop->logger, LOGGER_DEBUG, "%s", plist_xml);
free(plist_xml);
plist_t req_streams_node = plist_dict_get_item(req_root_node, "streams");
plist_t req_eiv_node = plist_dict_get_item(req_root_node, "eiv");
plist_t req_ekey_node = plist_dict_get_item(req_root_node, "ekey");
@@ -371,16 +360,30 @@ raop_handler_setup(raop_conn_t *conn,
plist_get_data_val(req_eiv_node, &eiv, &eiv_len);
memcpy(aesiv, eiv, 16);
logger_log(conn->raop->logger, LOGGER_DEBUG, "eiv_len = %llu", eiv_len);
char* ekey = NULL;
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;
plist_get_data_val(req_ekey_node, &ekey, &ekey_len);
logger_log(conn->raop->logger, LOGGER_DEBUG, "ekey_len = %llu", ekey_len);
// ekey is 72 bytes, aeskey is 16 bytes
str = utils_data_to_string((unsigned char *) ekey, ekey_len, 16);
logger_log(conn->raop->logger, LOGGER_DEBUG, "ekey:\n%s", str);
free (str);
int ret = fairplay_decrypt(conn->fairplay, (unsigned char*) ekey, aeskey);
logger_log(conn->raop->logger, LOGGER_DEBUG, "fairplay_decrypt ret = %d", ret);
unsigned char ecdh_secret[X25519_KEY_SIZE];
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);
// Time port
uint64_t timing_rport;
@@ -422,7 +425,7 @@ raop_handler_setup(raop_conn_t *conn,
plist_t stream_id_node = plist_dict_get_item(req_stream_node, "streamConnectionID");
uint64_t stream_connection_id;
plist_get_uint_val(stream_id_node, &stream_connection_id);
logger_log(conn->raop->logger, LOGGER_DEBUG, "streamConnectionID = %llu", stream_connection_id);
logger_log(conn->raop->logger, LOGGER_DEBUG, "streamConnectionID (needed for AES-CTR video decryption iv): %llu", stream_connection_id);
if (conn->raop_rtp_mirror) {
raop_rtp_init_mirror_aes(conn->raop_rtp_mirror, stream_connection_id);