Turn off many currently-irrelevant debug messages by setting their level to 4, meaning they will never be displayed.

Author: mikebrady

ap2_buffered_audio_processor.c

@@ -332,7 +332,7 @@ void *rtp_buffered_audio_processor(void *arg) {
 
     if (finished == 0) {
       pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 25000,
-                                       1); // 25 ms is a long time to wait!
+                                       4); // 25 ms is a long time to wait!
       if (blocks_read != 0) {
         if (conn->ap2_immediate_flush_requested != 0) {
           if (ap2_immediate_flush_requested == 0) {
@@ -422,9 +422,12 @@ void *rtp_buffered_audio_processor(void *arg) {
           } else if (conn->ap2_deferred_flush_requests[f].active != 0) {
             new_audio_block_needed = 1;
             debug(3,
-                  "deferred flush of block: %u. flushFromTS: %12u, flushFromSeq: %12u, "
+                  "deferred flush of block: %u, timestamp: %u, SSRC: \"%s\". flushFromTS: %12u, flushFromSeq: %12u, "
                   "flushUntilTS: %12u, flushUntilSeq: %12u, timestamp: %12u.",
-                  seq_no, conn->ap2_deferred_flush_requests[f].flushFromTS,
+                  seq_no, 
+                  timestamp,
+                  get_ssrc_name(payload_ssrc),
+                  conn->ap2_deferred_flush_requests[f].flushFromTS,
                   conn->ap2_deferred_flush_requests[f].flushFromSeq,
                   conn->ap2_deferred_flush_requests[f].flushUntilTS,
                   conn->ap2_deferred_flush_requests[f].flushUntilSeq, timestamp);
@@ -589,7 +592,7 @@ void *rtp_buffered_audio_processor(void *arg) {
                     uint32_t packet_size = player_put_packet(
                         payload_ssrc, sequence_number_for_player, timestamp, payload_pointer,
                         payload_length, mute, timestamp_difference, conn);
-                    debug(3, "block %u, timestamp %u, length %u sent to the player.", seq_no,
+                    debug(4, "block %u, timestamp %u, length %u sent to the player.", seq_no,
                           timestamp, packet_size);
                     sequence_number_for_player++;                 // simply increment
                     expected_timestamp = timestamp + packet_size; // for the next time

audio_alsa.c

@@ -1987,7 +1987,7 @@ static int do_play(void *buf, int samples) {
       }
 
       snd_pcm_state_t prior_state = state; // keep this for afterwards....
-      debug(3, "alsa: write %d frames.", samples);
+      debug(4, "alsa: write %d frames.", samples);
       ret = alsa_pcm_write(alsa_handle, buf, samples);
       if (ret == -EIO) {
         debug(1, "alsa: I/O Error.");
@@ -2380,7 +2380,7 @@ static void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg)
                                    dither_random_number_store, current_encoded_output_format);
 
           ret = do_play(silence, frames_of_silence);
-          debug(3, "Played %u frames of silence on %u channels, equal to %zu bytes.",
+          debug(4, "Played %u frames of silence on %u channels, equal to %zu bytes.",
                 frames_of_silence, CHANNELS_FROM_ENCODED_FORMAT(current_encoded_output_format),
                 size_of_silence_buffer);
           frame_count++;

dacp.c

@@ -517,7 +517,7 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) {
   while (1) {
     int result = 0;
     int32_t the_volume;
-    pthread_cleanup_debug_mutex_lock(&dacp_server_information_lock, 500000, 2);
+    pthread_cleanup_debug_mutex_lock(&dacp_server_information_lock, 500000, 4);
     if (dacp_server.scan_enable == 0) {
       metadata_hub_modify_prolog();
       int ch = (metadata_store.dacp_server_active != 0) ||

metadata_hub.c

@@ -373,7 +373,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
       vl = vl << 32;                          // shift them into the correct location
       uint64_t ul = ntohl(*(uint32_t *)(data + sizeof(uint32_t))); // and the low order 32 bits
       vl = vl + ul;
-      debug(3, "MH Item ID seen: \"%" PRIx64 "\" of length %u.", vl, length);
+      debug(4, "MH Item ID seen: \"%" PRIx64 "\" of length %u.", vl, length);
       if ((vl != metadata_store.item_id) || (metadata_store.item_id_is_valid == 0)) {
         metadata_store.item_id = vl;
         metadata_store.item_id_changed = 1;
@@ -528,14 +528,14 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
     case 'pcen':
       break;
     case 'mdst':
-      debug(3, "MH Metadata stream processing start.");
+      debug(4, "MH Metadata stream processing start.");
       metadata_packet_item_changed = 0;
       break;
     case 'mden':
       if (metadata_packet_item_changed != 0)
         debug(3, "MH Metadata stream processing end with changes.");
       else
-        debug(3, "MH Metadata stream processing end without changes.");
+        debug(4, "MH Metadata stream processing end without changes.");
       changed = metadata_packet_item_changed;
       break;
     case 'PICT':

player.c

@@ -402,7 +402,7 @@ static void swr_alloc_cleanup_handler(void *arg) {
 }
 
 static void av_packet_alloc_cleanup_handler(void *arg) {
-  debug(3, "av_packet_alloc_cleanup_handler");
+  debug(4, "av_packet_alloc_cleanup_handler");
   AVPacket **pkt = arg;
   av_packet_free(pkt);
 }
@@ -1144,7 +1144,7 @@ int64_t avframe_to_audio(rtsp_conn_info *conn, AVFrame *decoded_frame, uint8_t *
 
   int number_of_output_samples_expected = swr_get_out_samples(conn->swr, decoded_frame->nb_samples);
 
-  debug(3, "A maximum of %d output samples expected for %d input samples.",
+  debug(4, "A maximum of %d output samples expected for %d input samples.",
         number_of_output_samples_expected, decoded_frame->nb_samples);
   // allocate enough space for the required number of output channels
   // and the number of samples decoded
@@ -1155,10 +1155,10 @@ int64_t avframe_to_audio(rtsp_conn_info *conn, AVFrame *decoded_frame, uint8_t *
   int samples_generated =
       swr_convert(conn->swr, &pcm_audio, number_of_output_samples_expected,
                   (const uint8_t **)decoded_frame->extended_data, decoded_frame->nb_samples);
-  debug(3, "conversion time for %u incoming samples: %.3f milliseconds.", decoded_frame->nb_samples,
+  debug(4, "conversion time for %u incoming samples: %.3f milliseconds.", decoded_frame->nb_samples,
         (get_absolute_time_in_ns() - conversion_start_time) * 0.000001);
   if (samples_generated > 0) {
-    debug(3, "swr generated %d frames of %" PRId64 " channels.", samples_generated,
+    debug(4, "swr generated %d frames of %" PRId64 " channels.", samples_generated,
           conn->resampler_output_channels);
     // samples_generated will be different from
     // the number of samples input if the output rate is different from the input
@@ -2296,7 +2296,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn, int resync_requested) {
             uint64_t should_be_time;
             frame_to_local_time(curframe->timestamp, &should_be_time, conn);
             int64_t time_difference = should_be_time - get_absolute_time_in_ns();
-            debug(3, "Check packet from buffer %u, timestamp %u, %f seconds ahead.", conn->ab_read,
+            debug(4, "Check packet from buffer %u, timestamp %u, %f seconds ahead.", conn->ab_read,
                   curframe->timestamp, 0.000000001 * time_difference);
           } else {
             debug(3, "Check packet from buffer %u, empty.", conn->ab_read);
@@ -3210,8 +3210,8 @@ int stuff_buffer_soxr_32(int32_t *inptr, int length, sps_format_t l_output_forma
     };
   }
 
-  if (packets_processed % 1250 == 0) {
-    debug(3,
+  if ((packets_processed % 1250 == 0) && (stat_n > 0)) {
+    debug(4,
           "soxr_oneshot execution time in nanoseconds: mean, standard deviation and max "
           "for %" PRId32 " interpolations in the last "
           "1250 packets. %10.6f, %10.6f, %10.6f.",
@@ -4269,7 +4269,7 @@ void *player_thread_func(void *arg) {
               output_buffer_delay_time =
                   output_buffer_delay_time /
                   RATE_FROM_ENCODED_FORMAT(config.current_output_configuration);
-              debug(3,
+              debug(4,
                     "current_delay: %" PRId64 ", output_buffer_delay_time: %.3f, output rate: %u.",
                     current_delay, output_buffer_delay_time * 0.000000001,
                     RATE_FROM_ENCODED_FORMAT(config.current_output_configuration));
@@ -4352,8 +4352,9 @@ void *player_thread_func(void *arg) {
                       gap_to_fix = -inframe->timestamp_gap; // this is frames at the input rate
                       int64_t gap_to_fix_ns = (gap_to_fix * 1000000000) / conn->input_rate;
                       gap_to_fix = (gap_to_fix_ns *
-                                    RATE_FROM_ENCODED_FORMAT(config.current_output_configuration)) /
+                                    RATE_FROM_ENCODED_FORMAT(config.current_output_configuration) + 1000000000/2) /
                                    1000000000; // this is frames at the output rate
+                      debug(3, "gap_to_fix: %u frames at input rate, %" PRId64 " frames at output rate.", -inframe->timestamp_gap, gap_to_fix);
                       // debug(3, "due to timstamp gap of %d frames, skip %" PRId64 " output
                       // frames.", inframe->timestamp_gap, gap_to_fix);
                     }
@@ -4471,16 +4472,16 @@ void *player_thread_func(void *arg) {
                       amount_to_stuff = -1 * (inbuflength / 350);
                       if (amount_to_stuff == 0)
                         amount_to_stuff = -1;
-                      debug(3, "drop a frame, inbuflength is %d, amount_to_stuff is %d.",
+                      debug(4, "drop a frame, inbuflength is %d, amount_to_stuff is %d.",
                             inbuflength, amount_to_stuff);
                     } else if (centered_sync_error_ns < (-tolerance_ns)) {
                       amount_to_stuff = +1 * (inbuflength / 350);
                       if (amount_to_stuff == 0)
                         amount_to_stuff = 1;
-                      debug(3, "add a frame, inbuflength is %d, amount_to_stuff is %d.",
+                      debug(4, "add a frame, inbuflength is %d, amount_to_stuff is %d.",
                             inbuflength, amount_to_stuff);
                     } else {
-                      debug(3,
+                      debug(4,
                             "error is within tolerance: centered_sync_error_ns: %" PRId64
                             ", tolerance_ns: %" PRId64 " ns.",
                             centered_sync_error_ns, tolerance_ns);
@@ -4490,7 +4491,7 @@ void *player_thread_func(void *arg) {
               }
 
               if (amount_to_stuff)
-                debug(3,
+                debug(4,
                       //                          "stuff: %+d, sync_error: %+5.3f milliseconds.",
                       //                          amount_to_stuff, sync_error * 1000);
                       "stuff: %+d, sync_errors actual: %+5.3f milliseconds, bufferlength: %d, "
@@ -4775,19 +4776,23 @@ void *player_thread_func(void *arg) {
                         frames_to_skip -= play_samples;
                       } else {
 
-                        char *offset = conn->outbuf;
-                        offset +=
-                            frames_to_skip *
+                        
+
+                        size_t bytes_to_skip = frames_to_skip *
                             CHANNELS_FROM_ENCODED_FORMAT(config.current_output_configuration) *
                             sps_format_sample_size(
                                 FORMAT_FROM_ENCODED_FORMAT(config.current_output_configuration));
-                        config.output->play(offset, play_samples - frames_to_skip,
+
+                        char *play_starting_point = conn->outbuf + bytes_to_skip;
+                          
+                        config.output->play(play_starting_point, play_samples - frames_to_skip,
                                             play_samples_are_timed, inframe->timestamp,
                                             should_be_time);
 
-                        debug(3, "skipping the first %u frames in a packet of %u frames.",
+                        debug(3, "skipping the first %u frames (listed below) in a packet of %u frames.",
                               frames_to_skip, play_samples);
-                        debug_print_buffer(3, conn->outbuf, offset - conn->outbuf);
+
+                        debug_print_buffer(3, conn->outbuf, bytes_to_skip);
 
                         frames_played += play_samples - frames_to_skip;
                         frames_to_skip = 0;
@@ -4967,7 +4972,7 @@ static void player_send_volume_metadata(uint8_t vol_mode_both, double airplay_vo
 }
 
 void player_volume_without_notification(double airplay_volume, rtsp_conn_info *conn) {
-  debug_mutex_lock(&conn->volume_control_mutex, 5000, 1);
+  debug_mutex_lock(&conn->volume_control_mutex, 5000, 4);
   // first, see if we are hw only, sw only, both with hw attenuation on the top or both with sw
   // attenuation on top
 
@@ -5149,7 +5154,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
       double temp_fix_volume = 65536.0 * pow(10, software_attenuation / 2000);
 
       if (config.ignore_volume_control == 0)
-        debug(3, "Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of %f",
+        debug(4, "Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of %f",
               software_attenuation, temp_fix_volume, airplay_volume);
       else
         debug(3, "Software attenuation set to %f, i.e %f out of 65,536. Volume control is ignored.",
@@ -5158,7 +5163,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
       conn->fix_volume = temp_fix_volume;
     }
     if (conn != NULL)
-      debug(3, "Connection %d: AirPlay Volume set to %.3f, Output Level set to: %.2f dB.",
+      debug(4, "Connection %d: AirPlay Volume set to %.3f, Output Level set to: %.2f dB.",
             conn->connection_number, airplay_volume, scaled_attenuation / 100.0);
     else
       debug(3, "AirPlay Volume set to %.3f, Output Level set to: %.2f dB. NULL conn.",
@@ -5176,7 +5181,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
       config.output->mute(0);
     conn->software_mute_enabled = 0;
 
-    debug(3,
+    debug(4,
           "player_volume_without_notification: volume mode is %d, airplay volume is %.2f, "
           "software_attenuation dB: %.2f, hardware_attenuation dB: %.2f, muting "
           "is disabled.",
@@ -5185,7 +5190,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
   // here, store the volume for possible use in the future
   config.airplay_volume = airplay_volume;
   conn->own_airplay_volume = airplay_volume;
-  debug_mutex_unlock(&conn->volume_control_mutex, 3);
+  debug_mutex_unlock(&conn->volume_control_mutex, 4);
 }
 
 void player_volume(double airplay_volume, rtsp_conn_info *conn) {