From 3de7e9a5c5110831070e97f3723d9b3d430f5690 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 12:09:49 +0000 Subject: [PATCH 1/5] Look for at least 0.1 seconds of leadtime, ensure a master clock is at least 0.275 seconds old before use, quieten a few debug messages. --- player.c | 5 +++-- rtp.c | 6 +++--- rtsp.c | 10 +++++----- 3 files changed, 11 insertions(+), 10 deletions(-) diff --git a/player.c b/player.c index 6e1ee80d..6131ad4c 100644 --- a/player.c +++ b/player.c @@ -1062,8 +1062,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->first_packet_time_to_play = should_be_time; int64_t lt = conn->first_packet_time_to_play - local_time_now; - - debug(1, "Connection %d: Lead time for first frame %" PRId64 ": %f seconds.", + + if (lt < 100000000) + debug(1, "Connection %d: Short lead time for first frame %" PRId64 ": %f seconds.", conn->connection_number, conn->first_packet_timestamp, lt * 0.000000001); int64_t lateness = local_time_now - conn->first_packet_time_to_play; diff --git a/rtp.c b/rtp.c index f80e32ae..401f4dba 100644 --- a/rtp.c +++ b/rtp.c @@ -1310,7 +1310,7 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, // if the master clock and the anchor clock are the same // wait at least this time before using the new master clock // note that mastershipo may be backdated - if (duration_of_mastership < 100000000) { + if (duration_of_mastership < 275000000) { debug(3, "master not old enough yet: %f ms", 0.000001 * duration_of_mastership); response = clock_not_ready; } else if ((duration_of_mastership > 5000000000) || @@ -2254,7 +2254,7 @@ void *rtp_buffered_audio_processor(void *arg) { int streaming_has_started = 0; int play_enabled = 0; uint32_t flush_from_timestamp; - double requested_lead_time = 0.0; // normal lead time minimum -- maybe it should be about 0.1 + double requested_lead_time = 0.1; // normal lead time minimum -- maybe it should be about 0.1 // wait until our timing information is valid @@ -2642,7 +2642,7 @@ void *rtp_buffered_audio_processor(void *arg) { if (pkt->size) { // if (0) { if (pkt->size <= 7) { // no idea about this... - debug(1, "malformed AAC packet skipped."); + debug(2, "malformed AAC packet skipped."); } else { ret = avcodec_send_packet(codec_context, pkt); diff --git a/rtsp.c b/rtsp.c index 177a4b81..4b0827bf 100644 --- a/rtsp.c +++ b/rtsp.c @@ -697,7 +697,7 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_cancel(conns[i]->thread); - debug(1, "Connection %d: cancelled.", conns[i]->connection_number); + debug(2, "Connection %d: cancelled.", conns[i]->connection_number); } } for (i = 0; i < nconns; i++) { @@ -706,7 +706,7 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_join(conns[i]->thread, NULL); - debug(1, "Connection %d: joined.", conns[i]->connection_number); + debug(2, "Connection %d: joined.", conns[i]->connection_number); free(conns[i]); conns[i] = NULL; } @@ -2625,7 +2625,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) uint8_t isRemoteControlOnlyBoolean = 0; plist_get_bool_val(isRemoteControlOnly, &isRemoteControlOnlyBoolean); if (isRemoteControlOnlyBoolean != 0) { - debug(1, "Connection %d: SETUP: Remote Control setup detected.", + debug(2, "Connection %d: SETUP: Remote Control setup detected.", conn->connection_number); conn->airplay_stream_category = remote_control_stream; } else { @@ -2825,7 +2825,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->connection_number, err); } - debug(1, "Connection %d: TCP Remote Control event port opened: %u.", + debug(2, "Connection %d: TCP Remote Control event port opened: %u.", conn->connection_number, conn->local_event_port); if (conn->rtp_event_thread != NULL) debug(1, "previous rtp_event_thread allocation not freed, it seems."); @@ -3056,7 +3056,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) resp->respcode = 200; } else if (conn->airplay_stream_category == remote_control_stream) { debug(2, "Connection %d: SETUP: Remote Control Stream received.", conn->connection_number); - debug_log_rtsp_message(1, "Remote Control Stream stream (second) message", req); + debug_log_rtsp_message(2, "Remote Control Stream stream (second) message", req); resp->respcode = 200; } else { From dbebdca84d95ee80d34d7eef8c6b29e581b315bd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 15:08:16 +0000 Subject: [PATCH 2/5] quieten a debug message --- dacp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dacp.c b/dacp.c index d6964133..7184ed73 100644 --- a/dacp.c +++ b/dacp.c @@ -481,7 +481,7 @@ void dacp_monitor_port_update_callback(char *dacp_id, uint16_t port) { // metadata_store.dacp_server_active = dacp_server.scan_enable; // metadata_hub_modify_epilog(ch); } else { - debug(1, "dacp port monitor reporting on an out-of-use remote."); + debug(2, "dacp port monitor reporting on an out-of-use remote."); } } pthread_cond_signal(&dacp_server_information_cv); From fd3d461a164bd4afcfeb76b26bdc7140f2570353 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 15:09:05 +0000 Subject: [PATCH 3/5] stop removing the play lock at the end of a play session. That's the job of the rtsp thread. --- player.c | 2 +- rtsp.c | 21 +++++++++++++++++---- 2 files changed, 18 insertions(+), 5 deletions(-) diff --git a/player.c b/player.c index 6131ad4c..1feee08f 100644 --- a/player.c +++ b/player.c @@ -1717,7 +1717,7 @@ void player_thread_cleanup_handler(void *arg) { terminate_decoders(conn); // reset_anchor_info(conn); - release_play_lock(conn); + // release_play_lock(conn); conn->rtp_running = 0; pthread_setcancelstate(oldState, NULL); debug(2, "Connection %d: player terminated.", conn->connection_number); diff --git a/rtsp.c b/rtsp.c index 4b0827bf..959944ac 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1879,6 +1879,7 @@ void handle_get(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused) req->contentlength); resp->respcode = 500; } + void handle_post(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused)) rtsp_message *req, __attribute((unused)) rtsp_message *resp) { @@ -2480,6 +2481,9 @@ void teardown_phase_two(rtsp_conn_info *conn) { debug(2, "Connection %d: TEARDOWN mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); + debug(1, "Connection %d: TEARDOWN (AP2) release play lock on %s.", conn->connection_number, + get_category_string(conn->airplay_stream_category)); + release_play_lock(conn); } } @@ -2533,6 +2537,9 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message "TEARDOWN: synchronously terminating the player thread of RTSP conversation thread %d (2).", conn->connection_number); player_stop(conn); + release_play_lock(conn); + debug(1, "TEARDOWN: release play lock on RTSP conversation thread %d.", + conn->connection_number); activity_monitor_signify_activity(0); // inactive, and should be after command_stop() debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); @@ -2800,6 +2807,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); + + resp->respcode = 200; } else { @@ -2862,6 +2871,9 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP on %s. A \"streams\" array has been found", conn->connection_number, get_category_string(conn->airplay_stream_category)); if (conn->airplay_stream_category == ptp_stream) { + debug(1, "Connection %d: SETUP get_play_lock.", + conn->connection_number); + get_play_lock(conn); // get stream[0] plist_t stream0 = plist_array_get_item(streams, 0); @@ -2939,7 +2951,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) case 96: { debug(1, "Connection %d. Realtime Audio Stream Detected.", conn->connection_number); debug_log_rtsp_message(2, "Realtime Audio Stream SETUP incoming message", req); - get_play_lock(conn); + // get_play_lock(conn); conn->airplay_stream_type = realtime_stream; // bind a new UDP port and get a socket conn->local_realtime_audio_port = 0; // any port @@ -2999,7 +3011,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(1, "SETUP on Connection %d. Buffered Audio Stream Detected.", conn->connection_number); debug_log_rtsp_message(2, "Buffered Audio Stream SETUP incoming message", req); - get_play_lock(conn); + // get_play_lock(conn); conn->airplay_stream_type = buffered_stream; // get needed stuff @@ -3229,7 +3241,7 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, if (!strncmp(cp, "volume: ", strlen("volume: "))) { float volume = atof(cp + strlen("volume: ")); - debug(2, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, + debug(1, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, volume); // if we are playing, go ahead and change the volume if (try_to_hold_play_lock(conn) == 0) { @@ -3969,7 +3981,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r if ((req->content) && (req->contentlength == strlen("volume\r\n")) && strstr(req->content, "volume") == req->content) { - debug(2, "Connection %d: Current volume (%.6f) requested", conn->connection_number, + debug(1, "Connection %d: Current volume (%.6f) requested", conn->connection_number, config.airplay_volume); char *p = malloc(128); // will be automatically deallocated with the response is deleted if (p) { @@ -4078,6 +4090,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: ANNOUNCE", conn->connection_number); + debug(1, "Connection %d: ANNOUNCE get_play_lock()", conn->connection_number); int get_play_status = get_play_lock(conn); if (get_play_status != -1) { debug(3, "Connection %d: ANNOUNCE has acquired play lock.", conn->connection_number); From 6a58eae3141c26ebc07721cc4a49d3daf84009c7 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 17:37:16 +0000 Subject: [PATCH 4/5] Quieten a few debug messasges. --- rtsp.c | 14 ++++---------- shairport.c | 4 ++-- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/rtsp.c b/rtsp.c index 959944ac..6bc6c1a0 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1345,7 +1345,8 @@ int msg_write_response(rtsp_conn_info *conn, rtsp_message *resp) { }; struct response_t responses[] = { - {200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {501, "Not Implemented"}}; + {200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {451, "Unavailable"}, {501, "Not Implemented"}}; + // 451 is really "Unavailable For Legal Reasons"! int found = 0; char *respcode_text = "Unauthorized"; for (i = 0; i < sizeof(responses) / sizeof(struct response_t); i++) { @@ -2481,8 +2482,6 @@ void teardown_phase_two(rtsp_conn_info *conn) { debug(2, "Connection %d: TEARDOWN mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); - debug(1, "Connection %d: TEARDOWN (AP2) release play lock on %s.", conn->connection_number, - get_category_string(conn->airplay_stream_category)); release_play_lock(conn); } } @@ -2538,8 +2537,6 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message conn->connection_number); player_stop(conn); release_play_lock(conn); - debug(1, "TEARDOWN: release play lock on RTSP conversation thread %d.", - conn->connection_number); activity_monitor_signify_activity(0); // inactive, and should be after command_stop() debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); @@ -2871,8 +2868,6 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP on %s. A \"streams\" array has been found", conn->connection_number, get_category_string(conn->airplay_stream_category)); if (conn->airplay_stream_category == ptp_stream) { - debug(1, "Connection %d: SETUP get_play_lock.", - conn->connection_number); get_play_lock(conn); // get stream[0] plist_t stream0 = plist_array_get_item(streams, 0); @@ -3241,7 +3236,7 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, if (!strncmp(cp, "volume: ", strlen("volume: "))) { float volume = atof(cp + strlen("volume: ")); - debug(1, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, + debug(2, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, volume); // if we are playing, go ahead and change the volume if (try_to_hold_play_lock(conn) == 0) { @@ -3981,7 +3976,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r if ((req->content) && (req->contentlength == strlen("volume\r\n")) && strstr(req->content, "volume") == req->content) { - debug(1, "Connection %d: Current volume (%.6f) requested", conn->connection_number, + debug(2, "Connection %d: Current volume (%.6f) requested", conn->connection_number, config.airplay_volume); char *p = malloc(128); // will be automatically deallocated with the response is deleted if (p) { @@ -4090,7 +4085,6 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: ANNOUNCE", conn->connection_number); - debug(1, "Connection %d: ANNOUNCE get_play_lock()", conn->connection_number); int get_play_status = get_play_lock(conn); if (get_play_status != -1) { debug(3, "Connection %d: ANNOUNCE has acquired play lock.", conn->connection_number); diff --git a/shairport.c b/shairport.c index b1faf5c9..ecba335a 100644 --- a/shairport.c +++ b/shairport.c @@ -1459,10 +1459,10 @@ void exit_function() { if (config.daemonise) debug(1, "libdaemon parent exit"); else - debug(1, "exit"); + debug(1, "exit_function libdaemon exit"); } #else - debug(1, "exit"); + debug(1, "exit_function exit"); #endif } else { debug(1, "emergency exit"); From 107bc71e56058bd1aee25f89ccb394417958924a Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 17:47:45 +0000 Subject: [PATCH 5/5] Stop checking that the timing peers are within the same subnet. --- rtsp.c | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/rtsp.c b/rtsp.c index 6bc6c1a0..7f78b211 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2725,10 +2725,11 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) char buf[32]; memset(buf, 0, sizeof(buf)); inet_ntop(AF_INET6, (void *)&addr6->sin6_addr, buf, sizeof(buf)); - if (!different) { + // don't insist there are in the same subnet... + //if (!different) { // debug(1, "%s is in the same subnet as %s.", buf, ip_address); plist_array_append_item(addresses, plist_new_string(buf)); - } + //} } } } else if (inet_pton(AF_INET, ip_address, &pa4->sin_addr) == 1) { @@ -2738,15 +2739,17 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) ((iap->ifa_flags & IFF_LOOPBACK) == 0) && (iap->ifa_addr->sa_family == AF_INET)) { struct sockaddr_in *addr = (struct sockaddr_in *)(iap->ifa_addr); - struct sockaddr_in *mask = (struct sockaddr_in *)(iap->ifa_netmask); - if ((addr->sin_addr.s_addr & mask->sin_addr.s_addr) == - (pa4->sin_addr.s_addr & mask->sin_addr.s_addr)) { + // not needed if not checking for same subnet + // struct sockaddr_in *mask = (struct sockaddr_in *)(iap->ifa_netmask); + // if ((addr->sin_addr.s_addr & mask->sin_addr.s_addr) == + // (pa4->sin_addr.s_addr & mask->sin_addr.s_addr)) { char buf[32]; memset(buf, 0, sizeof(buf)); inet_ntop(AF_INET, (void *)&addr->sin_addr, buf, sizeof(buf)); + // no longer insisting they are in the same subnet // debug(1, "%s is in the same subnet as %s.", buf, ip_address); plist_array_append_item(addresses, plist_new_string(buf)); - } + // } } } } else {