From 4090b2d8fb383ad8873d2c4538da9de9a0a26136 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 22 Jul 2021 13:23:57 +0100 Subject: [PATCH] Avoid repreatedly asking Avahi to monitor for the same DACP-ID. Quieten some debug messages. --- mdns_avahi.c | 94 +++++++++++++++++++-------------------- rtp.c | 121 +++++++++++++++++++++++++++++---------------------- rtsp.c | 53 +++++++++++----------- 3 files changed, 142 insertions(+), 126 deletions(-) diff --git a/mdns_avahi.c b/mdns_avahi.c index 9b53a539..c4568078 100644 --- a/mdns_avahi.c +++ b/mdns_avahi.c @@ -104,7 +104,7 @@ static void resolve_callback(AvahiServiceResolver *r, AVAHI_GCC_UNUSED AvahiIfIn while (*dacpid == '0') dacpid++; // skip any leading zeroes if (strcmp(dacpid, dbs->dacp_id) == 0) { - debug(1, "resolve_callback: client dacp_id \"%s\" dacp port: %u.", dbs->dacp_id, port); + debug(3, "resolve_callback: client dacp_id \"%s\" dacp port: %u.", dbs->dacp_id, port); #ifdef CONFIG_DACP_CLIENT dacp_monitor_port_update_callback(dacpid, port); #endif @@ -318,50 +318,47 @@ static void client_callback(AvahiClient *c, AvahiClientState state, } } -static int avahi_update(char **txt_records, - char **secondary_txt_records) { +static int avahi_update(char **txt_records, char **secondary_txt_records) { // debug(1, "avahi_update."); -/* - service_name = strdup(ap1name); - if (ap2name != NULL) - ap2_service_name = strdup(ap2name); - port = srvport; -*/ + /* + service_name = strdup(ap1name); + if (ap2name != NULL) + ap2_service_name = strdup(ap2name); + port = srvport; + */ int err = 0; AvahiIfIndex selected_interface; - if (config.interface != NULL) - selected_interface = config.interface_index; - else - selected_interface = AVAHI_IF_UNSPEC; + if (config.interface != NULL) + selected_interface = config.interface_index; + else + selected_interface = AVAHI_IF_UNSPEC; if (txt_records != NULL) { if (text_record_string_list) avahi_string_list_free(text_record_string_list); - text_record_string_list = - avahi_string_list_new_from_array((const char **)txt_records, -1); - err = avahi_entry_group_update_service_txt_strlst(group, selected_interface, AVAHI_PROTO_UNSPEC, 0, - service_name, config.regtype, NULL, - text_record_string_list); + text_record_string_list = avahi_string_list_new_from_array((const char **)txt_records, -1); + err = avahi_entry_group_update_service_txt_strlst(group, selected_interface, AVAHI_PROTO_UNSPEC, + 0, service_name, config.regtype, NULL, + text_record_string_list); if (err != 0) - debug(1,"avahi_update error updating primary txt records."); + debug(1, "avahi_update error updating primary txt records."); } if (secondary_txt_records != NULL) { if (ap2_text_record_string_list) avahi_string_list_free(ap2_text_record_string_list); ap2_text_record_string_list = - avahi_string_list_new_from_array((const char **)secondary_txt_records, -1); - err = avahi_entry_group_update_service_txt_strlst(group, selected_interface, AVAHI_PROTO_UNSPEC, 0, - ap2_service_name, config.regtype2, NULL, - ap2_text_record_string_list); + avahi_string_list_new_from_array((const char **)secondary_txt_records, -1); + err = avahi_entry_group_update_service_txt_strlst(group, selected_interface, AVAHI_PROTO_UNSPEC, + 0, ap2_service_name, config.regtype2, NULL, + ap2_text_record_string_list); if (err != 0) - debug(1,"avahi_update error updating secondary txt records."); + debug(1, "avahi_update error updating secondary txt records."); } return 0; } - static int avahi_register(char *ap1name, char *ap2name, int srvport, char **txt_records, char **secondary_txt_records) { // debug(1, "avahi_register."); @@ -446,7 +443,7 @@ static void avahi_unregister(void) { void avahi_dacp_monitor_start(void) { // debug(1, "avahi_dacp_monitor_start."); memset((void *)&private_dbs, 0, sizeof(dacp_browser_struct)); - debug(1, "avahi_dacp_monitor_start Avahi DACP monitor successfully started"); + debug(2, "avahi_dacp_monitor_start Avahi DACP monitor successfully started"); return; } @@ -454,28 +451,33 @@ void avahi_dacp_monitor_set_id(const char *dacp_id) { // debug(1, "avahi_dacp_monitor_set_id: Search for DACP ID \"%s\".", t); dacp_browser_struct *dbs = &private_dbs; - if (dbs->dacp_id) - free(dbs->dacp_id); - if (dacp_id == NULL) - dbs->dacp_id = NULL; - else { - char *t = strdup(dacp_id); - if (t) { - dbs->dacp_id = t; - avahi_threaded_poll_lock(tpoll); - if (dbs->service_browser) - avahi_service_browser_free(dbs->service_browser); + if (((dbs->dacp_id) && (dacp_id) && (strcmp(dbs->dacp_id, dacp_id) == 0)) || + ((dbs->dacp_id == NULL) && (dacp_id == NULL))) { + debug(3, "no change..."); + } else { + if (dbs->dacp_id) + free(dbs->dacp_id); + if (dacp_id == NULL) + dbs->dacp_id = NULL; + else { + char *t = strdup(dacp_id); + if (t) { + dbs->dacp_id = t; + avahi_threaded_poll_lock(tpoll); + if (dbs->service_browser) + avahi_service_browser_free(dbs->service_browser); - if (!(dbs->service_browser = - avahi_service_browser_new(client, AVAHI_IF_UNSPEC, AVAHI_PROTO_UNSPEC, "_dacp._tcp", - NULL, 0, browse_callback, (void *)dbs))) { - warn("failed to create avahi service browser: %s\n", - avahi_strerror(avahi_client_errno(client))); + if (!(dbs->service_browser = + avahi_service_browser_new(client, AVAHI_IF_UNSPEC, AVAHI_PROTO_UNSPEC, + "_dacp._tcp", NULL, 0, browse_callback, (void *)dbs))) { + warn("failed to create avahi service browser: %s\n", + avahi_strerror(avahi_client_errno(client))); + } + avahi_threaded_poll_unlock(tpoll); + debug(2, "dacp_monitor for \"%s\"", dacp_id); + } else { + warn("avahi_dacp_set_id: can not allocate a dacp_id string in dacp_browser_struct."); } - avahi_threaded_poll_unlock(tpoll); - debug(1,"dacp_monitor for \"%s\"", dacp_id); - } else { - warn("avahi_dacp_set_id: can not allocate a dacp_id string in dacp_browser_struct."); } } } diff --git a/rtp.c b/rtp.c index 1b2cffad..e074e113 100644 --- a/rtp.c +++ b/rtp.c @@ -290,8 +290,8 @@ void *rtp_control_receiver(void *arg) { obfp += 2; }; *obfp = 0; - - + + // get raw timestamp information // I think that a good way to understand these timestamps is that // (1) the rtlt below is the timestamp of the frame that should be playing at the @@ -302,19 +302,19 @@ void *rtp_control_receiver(void *arg) { // Thus, (3) the latency can be calculated by subtracting the second from the // first. // There must be more to it -- there something missing. - + // In addition, it seems that if the value of the short represented by the second // pair of bytes in the packet is 7 // then an extra time lag is expected to be added, presumably by // the AirPort Express. - + // Best guess is that this delay is 11,025 frames. - + uint32_t rtlt = nctohl(&packet[4]); // raw timestamp less latency uint32_t rt = nctohl(&packet[16]); // raw timestamp - + uint32_t fl = nctohs(&packet[2]); // - + debug(1,"Sync Packet of %d bytes received: \"%s\", flags: %d, timestamps %u and %u, giving a latency of %d frames.",plen,obf,fl,rt,rtlt,rt-rtlt); //debug(1,"Monotonic timestamps are: %" PRId64 " and %" PRId64 " @@ -1271,18 +1271,21 @@ int long_time_notifcation_done = 0; int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, uint64_t *anchorLocalTime) { uint64_t actual_clock_id, actual_time_of_sample, actual_offset, start_of_mastership; - int response = ptp_get_clock_info(&actual_clock_id, &actual_time_of_sample, &actual_offset, &start_of_mastership); + int response = ptp_get_clock_info(&actual_clock_id, &actual_time_of_sample, &actual_offset, + &start_of_mastership); if (response == clock_ok) { uint64_t time_now = get_absolute_time_in_ns(); int64_t time_since_sample = time_now - actual_time_of_sample; if (time_since_sample > 10000000000) { if (long_time_notifcation_done == 0) { - debug(1,"The last PTP timing sample is pretty old: %f seconds.", 0.000000001 * time_since_sample); + debug(1, "The last PTP timing sample is pretty old: %f seconds.", + 0.000000001 * time_since_sample); long_time_notifcation_done = 1; } } else if ((time_since_sample < 2000000000) && (long_time_notifcation_done != 0)) { - debug(1,"The last PTP timing sample is no longer too old: %f seconds.", 0.000000001 * time_since_sample); + debug(1, "The last PTP timing sample is no longer too old: %f seconds.", + 0.000000001 * time_since_sample); long_time_notifcation_done = 0; } @@ -1296,11 +1299,11 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, // using the master clock timing if (actual_clock_id == conn->anchor_clock) { - // 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 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 < 1500000000) { - debug(3,"master not old enough yet: %f ms", 0.000001 * duration_of_mastership); + debug(3, "master not old enough yet: %f ms", 0.000001 * duration_of_mastership); response = clock_not_ready; } else if ((duration_of_mastership > 5000000000) || (conn->last_anchor_info_is_valid == 0)) { @@ -1314,7 +1317,8 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, conn->last_anchor_info_is_valid = 1; if (conn->anchor_clock_is_new != 0) debug(1, - "Connection %d: Clock %" PRIx64 " is now the new anchor clock and master clock. History: %f milliseconds.", + "Connection %d: Clock %" PRIx64 + " is now the new anchor clock and master clock. History: %f milliseconds.", conn->connection_number, conn->anchor_clock, 0.000001 * duration_of_mastership); conn->anchor_clock_is_new = 0; } @@ -1326,16 +1330,19 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, // so, if the anchor has not changed, it must be that the master clock has changed if (conn->anchor_clock_is_new != 0) - debug(1, + debug(3, "Connection %d: Anchor clock has changed to %" PRIx64 ", master clock is: %" PRIx64 ". History: %f milliseconds.", - conn->connection_number, conn->anchor_clock, actual_clock_id, 0.000001 * duration_of_mastership); + conn->connection_number, conn->anchor_clock, actual_clock_id, + 0.000001 * duration_of_mastership); if ((conn->last_anchor_info_is_valid != 0) && (conn->anchor_clock_is_new == 0)) { int64_t time_since_last_update = get_absolute_time_in_ns() - conn->last_anchor_time_of_update; if (time_since_last_update > 5000000000) { - debug(1, "Connection %d: Master clock has changed to %" PRIx64 ". History: %f milliseconds.", + debug(1, + "Connection %d: Master clock has changed to %" PRIx64 + ". History: %f milliseconds.", conn->connection_number, actual_clock_id, 0.000001 * duration_of_mastership); // here we adjust the time of the anchor rtptime // we know its local time, so we use the new clocks's offset to @@ -2157,7 +2164,8 @@ void *rtp_buffered_audio_processor(void *arg) { av_opt_set_int(swr, "in_channel_layout", AV_CH_LAYOUT_STEREO, 0); av_opt_set_int(swr, "out_channel_layout", AV_CH_LAYOUT_STEREO, 0); av_opt_set_int(swr, "in_sample_rate", conn->input_rate, 0); - av_opt_set_int(swr, "out_sample_rate", conn->input_rate, 0); // must match or the timing will be wrong` + av_opt_set_int(swr, "out_sample_rate", conn->input_rate, + 0); // must match or the timing will be wrong` av_opt_set_sample_fmt(swr, "in_sample_fmt", AV_SAMPLE_FMT_FLTP, 0); enum AVSampleFormat av_format; @@ -2280,9 +2288,14 @@ void *rtp_buffered_audio_processor(void *arg) { if ((blocks_read != 0) && (seq_no >= flushUntilSeq)) { // we have reached or overshot the flushUntilSeq block if (flushUntilSeq != seq_no) - debug(2, "flush request ended with flushUntilSeq %u overshot at %u, flushUntilTS: %u, incoming timestamp: %u.", flushUntilSeq, seq_no, flushUntilTS, timestamp); + debug(2, + "flush request ended with flushUntilSeq %u overshot at %u, flushUntilTS: %u, " + "incoming timestamp: %u.", + flushUntilSeq, seq_no, flushUntilTS, timestamp); else - debug(2, "flush request ended with flushUntilSeq, flushUntilTS: %u, incoming timestamp: %u", flushUntilSeq, flushUntilTS, timestamp); + debug(2, + "flush request ended with flushUntilSeq, flushUntilTS: %u, incoming timestamp: %u", + flushUntilSeq, flushUntilTS, timestamp); conn->ap2_flush_requested = 0; flush_request_active = 0; flush_newly_requested = 0; @@ -2301,7 +2314,6 @@ void *rtp_buffered_audio_processor(void *arg) { if (flush_newly_complete) { debug(2, "Flush Complete."); blocks_read_since_flush = 0; - } if (play_newly_stopped != 0) @@ -2329,9 +2341,10 @@ void *rtp_buffered_audio_processor(void *arg) { // is there space in the player thread's buffer system? unsigned int player_buffer_size, player_buffer_occupancy; get_audio_buffer_size_and_occupancy(&player_buffer_size, &player_buffer_occupancy, conn); - //debug(1,"player buffer size and occupancy: %u and %u", player_buffer_size, player_buffer_occupancy); - if (player_buffer_occupancy > - ((requested_lead_time + 0.4) * conn->input_rate / 352)) { // must be greater than the lead time. + // debug(1,"player buffer size and occupancy: %u and %u", player_buffer_size, + // player_buffer_occupancy); + if (player_buffer_occupancy > ((requested_lead_time + 0.4) * conn->input_rate / + 352)) { // must be greater than the lead time. // if there is enough stuff in the player's buffer, sleep for a while and try again usleep(1000); // wait for a while } else { @@ -2358,26 +2371,26 @@ void *rtp_buffered_audio_processor(void *arg) { // it seems that some garbage blocks can be left after the flush, so // only accept them if they have sensible lead times if ((lead_time_ms < 5000.0) && (lead_time > -1000.0)) { - // if it's the very first block (thus no priming needed) - if ((blocks_read == 1) || (blocks_read_since_flush > 3)) { - if ((lead_time >= (int64_t)(requested_lead_time * 1000000000)) || - (streaming_has_started != 0)) { - if (streaming_has_started == 0) - debug( - 2, - "Connection %d: buffered audio starting frame: %u, lead time: %f seconds.", - conn->connection_number, pcm_buffer_read_point_rtptime, - 0.000000001 * lead_time); - // else { - // if (expected_rtptime != pcm_buffer_read_point_rtptime) - // debug(1,"actual rtptime is %u, expected rtptime is %u.", - // pcm_buffer_read_point_rtptime, expected_rtptime); - //} - // expected_rtptime = pcm_buffer_read_point_rtptime + 352; + // if it's the very first block (thus no priming needed) + if ((blocks_read == 1) || (blocks_read_since_flush > 3)) { + if ((lead_time >= (int64_t)(requested_lead_time * 1000000000)) || + (streaming_has_started != 0)) { + if (streaming_has_started == 0) + debug(2, + "Connection %d: buffered audio starting frame: %u, lead time: %f " + "seconds.", + conn->connection_number, pcm_buffer_read_point_rtptime, + 0.000000001 * lead_time); + // else { + // if (expected_rtptime != pcm_buffer_read_point_rtptime) + // debug(1,"actual rtptime is %u, expected rtptime is %u.", + // pcm_buffer_read_point_rtptime, expected_rtptime); + //} + // expected_rtptime = pcm_buffer_read_point_rtptime + 352; - // this is a diagnostic for introducing a timing error that will force the - // processing chain to resync - // clang-format off + // this is a diagnostic for introducing a timing error that will force the + // processing chain to resync + // clang-format off /* if ((not_first_time_out == 0) && (blocks_read >= 20)) { int timing_error = 150; @@ -2390,21 +2403,23 @@ void *rtp_buffered_audio_processor(void *arg) { not_first_time_out = 1; } */ - // clang-format on + // clang-format on - player_put_packet(0, 0, pcm_buffer_read_point_rtptime, - pcm_buffer + pcm_buffer_read_point, 352, conn); - streaming_has_started++; + player_put_packet(0, 0, pcm_buffer_read_point_rtptime, + pcm_buffer + pcm_buffer_read_point, 352, conn); + streaming_has_started++; + } } - } } else { - debug(2,"Dropping packet %u from block %u with out-of-range lead_time: %.3f seconds.", pcm_buffer_read_point_rtptime, seq_no, 0.001 * lead_time_ms); + debug(2, + "Dropping packet %u from block %u with out-of-range lead_time: %.3f seconds.", + pcm_buffer_read_point_rtptime, seq_no, 0.001 * lead_time_ms); } pcm_buffer_read_point_rtptime += 352; pcm_buffer_read_point += 352 * conn->input_bytes_per_frame; } else { - debug(1,"frame to local time error"); + debug(1, "frame to local time error"); } } else { usleep(1000); // wait before asking if play is enabled again @@ -2488,8 +2503,8 @@ void *rtp_buffered_audio_processor(void *arg) { // valid int64_t lead_time = should_be_time - get_absolute_time_in_ns(); debug(1, - "flush completed to seq: %u, flushUntilTS; %u with rtptime: %u, lead time: 0x%" PRIx64 - " nanoseconds, i.e. %f sec.", + "flush completed to seq: %u, flushUntilTS; %u with rtptime: %u, lead time: " + "0x%" PRIx64 " nanoseconds, i.e. %f sec.", seq_no, flushUntilTS, timestamp, lead_time, lead_time * 0.000000001); } else { debug(2, "flush completed to seq: %u with rtptime: %u.", seq_no, timestamp); diff --git a/rtsp.c b/rtsp.c index e087fbf1..ca5178cd 100644 --- a/rtsp.c +++ b/rtsp.c @@ -181,8 +181,7 @@ typedef struct { #ifdef CONFIG_AIRPLAY_2 void mdns_update_flags(uint32_t flags) { - snprintf(statusflagsString, sizeof(statusflagsString), "flags=0x%" PRIX32, - flags); + snprintf(statusflagsString, sizeof(statusflagsString), "flags=0x%" PRIX32, flags); mdns_update(NULL, secondary_txt_records); } #endif @@ -1939,9 +1938,9 @@ void handle_configure(rtsp_conn_info *conn __attribute__((unused)), debug_log_rtsp_message(2, "POST /configure response:", resp); } -void handle_feedback(__attribute__((unused)) rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, __attribute__((unused)) rtsp_message *resp) { - -} +void handle_feedback(__attribute__((unused)) rtsp_conn_info *conn, + __attribute__((unused)) rtsp_message *req, + __attribute__((unused)) rtsp_message *resp) {} void handle_post(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { resp->respcode = 200; @@ -1962,8 +1961,8 @@ void handle_post(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { } else if (strcmp(req->path, "/feedback") == 0) { handle_feedback(conn, req, resp); } else { - debug(1, "Connection %d: Unhandled POST %s Content-Length %d", conn->connection_number, req->path, - req->contentlength); + debug(2, "Connection %d: Unhandled POST %s Content-Length %d", conn->connection_number, + req->path, req->contentlength); debug_log_rtsp_message(2, "POST request", req); } } @@ -2202,13 +2201,12 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) plist_t item = plist_dict_get_item(stream0, "shk"); // session key uint64_t item_value = 0; plist_get_data_val(item, (char **)&conn->session_key, &item_value); - + // get the DACP-ID and Active Remote for remote control stuff - - + char *ar = msg_get_header(req, "Active-Remote"); if (ar) { - debug(1, "Connection %d: SETUP AP2 -- Active-Remote string seen: \"%s\".", + debug(3, "Connection %d: SETUP AP2 -- Active-Remote string seen: \"%s\".", conn->connection_number, ar); // get the active remote if (conn->dacp_active_remote) // this is in case SETUP was previously called @@ -2225,10 +2223,11 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->dacp_active_remote = NULL; } } - + ar = msg_get_header(req, "DACP-ID"); if (ar) { - debug(1, "Connection %d: SETUP AP2 -- DACP-ID string seen: \"%s\".", conn->connection_number, ar); + debug(3, "Connection %d: SETUP AP2 -- DACP-ID string seen: \"%s\".", conn->connection_number, + ar); if (conn->dacp_id) // this is in case SETUP was previously called free(conn->dacp_id); conn->dacp_id = strdup(ar); @@ -2299,8 +2298,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) ptp_send_control_message_string(conn->ap2_timing_peer_list_message); else debug(1, "No timing peer list!"); - //config.airplay_statusflags |= 1 << 10; // ReceiverSessionIsActive - //mdns_update_flags(config.airplay_statusflags); + // config.airplay_statusflags |= 1 << 10; // ReceiverSessionIsActive + // mdns_update_flags(config.airplay_statusflags); activity_monitor_signify_activity(1); player_prepare_to_play(conn); player_play(conn); @@ -2343,8 +2342,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) // this should be cancelled by an activity_monitor_signify_activity(1) // call in the SETRATEANCHORI handler, which should come up right away - //config.airplay_statusflags |= 1 << 10; // ReceiverSessionIsActive - //mdns_update_flags(config.airplay_statusflags); + // config.airplay_statusflags |= 1 << 10; // ReceiverSessionIsActive + // mdns_update_flags(config.airplay_statusflags); activity_monitor_signify_activity(0); player_play(conn); @@ -4178,15 +4177,15 @@ static void *rtsp_conversation_thread_func(void *pconn) { resp = msg_init(); pthread_cleanup_push(msg_cleanup_function, (void *)&resp); resp->respcode = 400; -/* - if (strcmp(req->method, "OPTIONS") != - 0) // the options message is very common, so don't log it until level 3 - debug_level = 2; - debug(debug_level, - "Connection %d: Received an RTSP Packet of type \"%s\":", conn->connection_number, - req->method), - debug_print_msg_headers(debug_level, req); -*/ + /* + if (strcmp(req->method, "OPTIONS") != + 0) // the options message is very common, so don't log it until level 3 + debug_level = 2; + debug(debug_level, + "Connection %d: Received an RTSP Packet of type \"%s\":", conn->connection_number, + req->method), + debug_print_msg_headers(debug_level, req); + */ apple_challenge(conn->fd, req, resp); hdr = msg_get_header(req, "CSeq"); @@ -4545,7 +4544,7 @@ void *rtsp_listen_loop(__attribute((unused)) void *arg) { secondary_txt_records[entry_number++] = featuresString; snprintf(statusflagsString, sizeof(statusflagsString), "flags=0x%" PRIX32, config.airplay_statusflags); - + secondary_txt_records[entry_number++] = statusflagsString; secondary_txt_records[entry_number++] = "protovers=1.1"; secondary_txt_records[entry_number++] = "acl=0";