Fix a D-Bus Test Client compilation bug; turn off lots of less relevant debug messages; change how blocks of audio very far in the future are handled; add pw=true to the Bonjour information for classic AirPlay when built for AirPlay 2.

.github/workflows/check_classic_mac_basic.yml

@@ -9,9 +9,7 @@ on:
     
 jobs:
   build:
-
-    runs-on: macos-15
-
+    runs-on: macos-latest
     steps:
     - uses: actions/checkout@v6.0.2
     - name: Install Dependencies

.github/workflows/docker-on-push-tag-or-pr.yaml

@@ -59,7 +59,7 @@ jobs:
           fi
       
       - name: Login to Docker Registry
-        uses: docker/login-action@v3.7.0
+        uses: docker/login-action@v4.0.0
         with:
           registry: ${{ secrets.DOCKER_REGISTRY }}
           username: ${{ secrets.DOCKER_REGISTRY_USER }}
@@ -67,13 +67,13 @@ jobs:
         if: needs.docker-vars.outputs.push_docker_image == 'true'
       
       - name: Set up QEMU
-        uses: docker/setup-qemu-action@v3.7.0
+        uses: docker/setup-qemu-action@v4.0.0
       
       - name: Set up Docker Buildx
-        uses: docker/setup-buildx-action@v3.12.0
+        uses: docker/setup-buildx-action@v4.0.0
       
       - name: Build and push ${{ matrix.name }}
-        uses: docker/build-push-action@v6.19.2
+        uses: docker/build-push-action@v7.0.0
         env:
           registry_and_name: ${{ secrets.DOCKER_REGISTRY }}/${{ secrets.DOCKER_IMAGE_NAME }}
         with:

README.md

@@ -16,7 +16,7 @@ Shairport Sync does not support AirPlay video or photo streaming.
 * Next Steps and Advanced Topics are [here](ADVANCED%20TOPICS/README.md).
 * Runtime settings are documented [here](scripts/shairport-sync.conf).
 * Build configuration options are detailed in [CONFIGURATION FLAGS.md](CONFIGURATION%20FLAGS.md).
-* The `man` page, detailing command line options, is [here](https://htmlpreview.github.io/?https://github.com/mikebrady/shairport-sync/blob/master/man/shairport-sync.html).
+* The `man` page, detailing command line options, is [here](https://raw.githack.com/mikebrady/shairport-sync/master/man/shairport-sync.1.xml).
 * Some advanced topics and developed in [ADVANCED TOPICS](https://github.com/mikebrady/shairport-sync/tree/master/ADVANCED%20TOPICS).
 
 # Features

ap2_buffered_audio_processor.c

@@ -198,6 +198,8 @@ void *rtp_buffered_audio_processor(void *arg) {
   int packets_played_in_this_sequence = 0;
 
   int play_enabled = 0;
+  
+  int very_early_packets_signalled = 0;
   // double requested_lead_time = 0.0; // normal lead time minimum -- maybe  it should be about 0.1
 
   // wait until our timing information is valid
@@ -332,7 +334,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) {
@@ -368,7 +370,7 @@ void *rtp_buffered_audio_processor(void *arg) {
 
 
           } else {
-            debug(3, "immediate flush of block %u until block %u", seq_no,
+            debug(4, "immediate flush of block %u until block %u", seq_no,
                   conn->ap2_immediate_flush_until_sequence_number);
             ap2_immediate_flush_requested = 1;
             new_audio_block_needed = 1; //
@@ -421,10 +423,13 @@ void *rtp_buffered_audio_processor(void *arg) {
             debug(2, "immediate flush was %s.", ap2_immediate_flush_requested == 0 ? "off" : "on");
           } 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, "
+            debug(4,
+                  "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);
@@ -441,27 +446,37 @@ void *rtp_buffered_audio_processor(void *arg) {
         // debug(1,"player buffer size and occupancy: %u and %u", player_buffer_size,
         // player_buffer_occupancy);
 
-        // If we are playing and there is room in the player buffer, go ahead and decode the block
+        // If we are playing and there is room in the player buffer, and the block it not too
+        // early, go ahead and decode the block
         // and send it to the player. Otherwise, keep the block and sleep for a while.
-        if ((play_enabled != 0) &&
-            (((1.0 * player_buffer_occupancy * conn->frames_per_packet) / conn->input_rate) <=
-             config.audio_decoded_buffer_desired_length)) {
-          uint64_t buffer_should_be_time;
-          frame_to_local_time(timestamp, &buffer_should_be_time, conn);
 
+        // calculate if there is room in the decoded audio buffer...
+        int audio_decoded_buffer_below_desired_length = ((1.0 * player_buffer_occupancy * conn->frames_per_packet) / conn->input_rate) <= config.audio_decoded_buffer_desired_length;
+        uint64_t buffer_should_be_time;
+        
+        int have_valid_time = (frame_to_local_time(timestamp, &buffer_should_be_time, conn) == 0);
+        
+        // calculate the lead time to make sure it's not too early...
+        int64_t lead_time = buffer_should_be_time - get_absolute_time_in_ns();
+                
+        if ((play_enabled != 0) && (have_valid_time != 0) &&
+            (audio_decoded_buffer_below_desired_length != 0) &&
+            (lead_time * 1E-9 < (config.audio_decoded_buffer_desired_length + 0.1))) {
+            
+            very_early_packets_signalled = 0; //reset very early packet warning signaller
+          
           // try to identify blocks that are timed to before the last buffer, and drop 'em
           int64_t time_from_last_buffer_time =
               buffer_should_be_time - previous_buffer_should_be_time;
 
           if ((packets_played_in_this_sequence == 0) || (time_from_last_buffer_time > 0)) {
-            int64_t lead_time = buffer_should_be_time - get_absolute_time_in_ns();
+            
             payload_length = 0;
             if (ssrc_is_recognised(payload_ssrc) != 0) {
               // prepare_decoding_chain(conn, payload_ssrc);
               unsigned long long new_payload_length = 0;
               payload_pointer = m + leading_free_space_length;
-              if ((lead_time < (int64_t)30000000000L) &&
-                  (lead_time >= 0)) { // only decipher the packet if it's not too late or too early
+              if (lead_time >= 0) { // only decipher the packet if it's not too late
                 int response = -1;    // guess that there is a problem
                 if (conn->session_key != NULL) {
                   unsigned char nonce[12];
@@ -589,7 +604,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
@@ -620,6 +635,11 @@ void *rtp_buffered_audio_processor(void *arg) {
           }
           new_audio_block_needed = 1; // the block has been used up and is no longer current
         } else {
+          if ((have_valid_time != 0) && (very_early_packets_signalled == 0) && (lead_time * 1E-9 > (config.audio_decoded_buffer_desired_length + 0.2))) {
+            debug(1, "incoming frame suddenly (?) has a lead time of %f seconds, with a desired decoded buffer length of %f.", 1.0 * lead_time * 1E-9, config.audio_decoded_buffer_desired_length);
+            very_early_packets_signalled = 1;
+          }
+        
           usleep(20000); // wait for a while
         }
       }

audio_alsa.c

@@ -1668,7 +1668,7 @@ static int set_mute_state() {
     }
     close_mixer();
   }
-  debug_mutex_unlock(&alsa_mixer_mutex, 3); // release the mutex
+  debug_mutex_unlock(&alsa_mixer_mutex, 4); // release the mutex
   pthread_cleanup_pop(0);                   // release the mutex
   pthread_setcancelstate(oldState, NULL);
   return response;
@@ -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.");
@@ -2163,7 +2163,7 @@ static int play(void *buf, int samples, __attribute__((unused)) int sample_type,
 }
 
 static void flush(void) {
-  pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1);
+  pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 4);
   if (alsa_backend_state != abm_disconnected) { // must be playing or connected...
     // do nothing for a flush if config.keep_dac_busy is true
     if (config.keep_dac_busy == 0) {
@@ -2172,7 +2172,7 @@ static void flush(void) {
   } else {
     debug(3, "alsa: flush() -- called on a disconnected alsa backend");
   }
-  debug_mutex_unlock(&alsa_mutex, 3);
+  debug_mutex_unlock(&alsa_mutex, 4);
   pthread_cleanup_pop(0); // release the mutex
 }
 
@@ -2194,7 +2194,7 @@ static void do_volume(double vol) { // caller is assumed to have the alsa_mutex
   int oldState;
   pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable
   set_volume = vol;
-  pthread_cleanup_debug_mutex_lock(&alsa_mixer_mutex, 1000, 1);
+  pthread_cleanup_debug_mutex_lock(&alsa_mixer_mutex, 1000, 4);
   if (volume_set_request && (open_mixer() == 0)) {
     if (has_softvol) {
       if (ctl && elem_id) {
@@ -2224,7 +2224,7 @@ static void do_volume(double vol) { // caller is assumed to have the alsa_mutex
     volume_set_request = 0; // any external request that has been made is now satisfied
     close_mixer();
   }
-  debug_mutex_unlock(&alsa_mixer_mutex, 3);
+  debug_mutex_unlock(&alsa_mixer_mutex, 4);
   pthread_cleanup_pop(0); // release the mutex
   pthread_setcancelstate(oldState, NULL);
 }
@@ -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++;

bonjour_strings.c

@@ -79,7 +79,8 @@ void build_bonjour_strings(__attribute((unused)) rtsp_conn_info *conn) {
   txt_records[entry_number++] = "cn=0,1";
   txt_records[entry_number++] = "da=true";
   txt_records[entry_number++] = "et=0,1";
-
+  if (config.password != NULL)
+    txt_records[entry_number++] = "pw=true";
   uint64_t features_hi = config.airplay_features;
   features_hi = (features_hi >> 32) & 0xffffffff;
   uint64_t features_lo = config.airplay_features;
@@ -136,7 +137,7 @@ void build_bonjour_strings(__attribute((unused)) rtsp_conn_info *conn) {
   txt_records[entry_number++] = "cn=0,1";
   txt_records[entry_number++] = "ch=2";
   txt_records[entry_number++] = "txtvers=1";
-  if (config.password == 0)
+  if (config.password == NULL)
     txt_records[entry_number++] = "pw=false";
   else
     txt_records[entry_number++] = "pw=true";

configure.ac

@@ -1,7 +1,7 @@
 # Process this file with autoconf to produce a configure script.
 
 AC_PREREQ([2.50])
-AC_INIT([shairport-sync], [5.0.1], [4265913+mikebrady@users.noreply.github.com])
+AC_INIT([shairport-sync], [5.0.2], [4265913+mikebrady@users.noreply.github.com])
 : ${CFLAGS="-O3"}
 : ${CXXFLAGS="-O3"}
 AM_INIT_AUTOMAKE([subdir-objects])

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':

mpris-service.c

@@ -167,7 +167,7 @@ void mpris_metadata_watcher(struct metadata_bundle *argc, __attribute__((unused)
   */
 
   // Build the metadata array
-  debug(2, "Build metadata");
+  debug(4, "Build metadata");
   GVariantBuilder *dict_builder = g_variant_builder_new(G_VARIANT_TYPE("a{sv}"));
 
   // Add in the artwork URI if it exists.

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
@@ -1449,10 +1449,10 @@ uint32_t player_put_packet(uint32_t ssrc, seq_t seqno, uint32_t actual_timestamp
 
   // ignore a request to flush that has been made before the first packet...
   if (conn->packet_count == 0) {
-    debug_mutex_lock(&conn->flush_mutex, 1000, 1);
+    debug_mutex_lock(&conn->flush_mutex, 1000, 4);
     conn->flush_requested = 0;
     conn->flush_rtp_timestamp = 0;
-    debug_mutex_unlock(&conn->flush_mutex, 3);
+    debug_mutex_unlock(&conn->flush_mutex, 4);
   }
 
   pthread_cleanup_debug_mutex_lock(&conn->ab_mutex, 30000, 0);
@@ -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(4, "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, "
@@ -4538,9 +4539,9 @@ void *player_thread_func(void *arg) {
                         inframe->timestamp, centered_sync_error_time * 1000, occ);
                   unsigned int s;
                   for (s = 0; s < conn->sync_samples_count; s++) {
-                    debug(3, "sample: %u, value: %.3f ms", s, sync_samples[s] * 0.000001);
+                    debug(4, "sample: %u, value: %.3f ms", s, sync_samples[s] * 0.000001);
                   }
-                  debug(3, "sync_history_length: %u, samples_count: %u, sample_index: %u",
+                  debug(4, "sync_history_length: %u, samples_count: %u, sample_index: %u",
                         sync_history_length, conn->sync_samples_count, last_sample_index);
                 }
                 sync_error_out_of_bounds = 0;
@@ -4767,7 +4768,7 @@ void *player_thread_func(void *arg) {
                       if (frames_to_skip > (unsigned int)play_samples) {
                         debug(3, "skipping a packet of %u frames.", play_samples);
                         debug_print_buffer(
-                            3, conn->outbuf,
+                            4, conn->outbuf,
                             play_samples *
                                 CHANNELS_FROM_ENCODED_FORMAT(config.current_output_configuration) *
                                 sps_format_sample_size(FORMAT_FROM_ENCODED_FORMAT(
@@ -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(4, "skipping the first %u frames in a packet of %u frames.",
                               frames_to_skip, play_samples);
-                        debug_print_buffer(3, conn->outbuf, offset - conn->outbuf);
+
+                        debug_print_buffer(4, 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) {

rtp.c

@@ -1520,7 +1520,7 @@ int frame_to_ptp_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info *
     *time = ltime;
     result = 0;
   } else {
-    debug(2, "frame_to_ptp_local_time can't get anchor local time information");
+    debug(4, "frame_to_ptp_local_time can't get anchor local time information");
   }
   return result;
 }

rtp.h

@@ -28,6 +28,7 @@ int local_time_to_frame(uint64_t time, uint32_t *frame, rtsp_conn_info *conn);
 int have_ptp_timing_information(rtsp_conn_info *conn);
 int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP,
                                    uint64_t *anchorLocalTime);
+void reset_ptp_anchor_info(rtsp_conn_info *conn);
 void *rtp_ap2_control_receiver(void *arg);
 void *rtp_realtime_audio_receiver(void *arg);
 void *rtp_ap2_timing_receiver(void *arg);

rtsp.c

@@ -235,7 +235,7 @@ typedef struct {
 void pc_queue_init(pc_queue *the_queue, char *items, size_t item_size, uint32_t number_of_items,
                    const char *name) {
   if (name)
-    debug(2, "Creating metadata queue \"%s\".", name);
+    debug(4, "Creating metadata queue \"%s\".", name);
   else
     debug(1, "Creating an unnamed metadata queue.");
   pthread_mutex_init(&the_queue->pc_queue_lock, NULL);
@@ -290,11 +290,11 @@ int pc_queue_add_item(pc_queue *the_queue, const void *the_stuff, int block) {
   int rc;
   if (the_queue) {
     if (block == 0) {
-      rc = debug_mutex_lock(&the_queue->pc_queue_lock, 10000, 2);
+      rc = debug_mutex_lock(&the_queue->pc_queue_lock, 10000, 4);
       if (rc == EBUSY)
         return EBUSY;
     } else
-      rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 1);
+      rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 4);
     if (rc)
       debug(1, "Error %d (\"%s\") locking for pc_queue_add_item. Block is %d.", rc, strerror(rc),
             block);
@@ -346,7 +346,7 @@ int pc_queue_add_item(pc_queue *the_queue, const void *the_stuff, int block) {
 int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) {
   int rc;
   if (the_queue) {
-    rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 1);
+    rc = debug_mutex_lock(&the_queue->pc_queue_lock, 50000, 4);
     if (rc)
       debug(1, "metadata queue \"%s\": error locking for pc_queue_get_item", the_queue->name);
     pthread_cleanup_push(pc_queue_cleanup_handler, (void *)the_queue);
@@ -367,7 +367,7 @@ int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) {
       i = 0;
     the_queue->toq = i;
     the_queue->count--;
-    debug(3, "metadata queue- \"%s\" %d/%d.", the_queue->name, the_queue->count,
+    debug(4, "metadata queue- \"%s\" %d/%d.", the_queue->name, the_queue->count,
           the_queue->capacity);
     rc = pthread_cond_signal(&the_queue->pc_queue_item_removed_signal);
     if (rc)
@@ -531,7 +531,7 @@ static void track_thread(rtsp_conn_info *conn) {
       die("could not reallocate memory for conns");
     }
   }
-  debug_mutex_unlock(&conns_lock, 3);
+  debug_mutex_unlock(&conns_lock, 4);
 }
 
 // note: connection numbers start at 1, so an except_this_one value of zero means "all threads"
@@ -575,34 +575,34 @@ void cleanup_threads(void) {
   int i;
   int connection_count = 0;
   // debug(2, "culling threads.");
-  debug_mutex_lock(&conns_lock, 1000000, 3);
+  debug_mutex_lock(&conns_lock, 1000000, 4);
   for (i = 0; i < nconns; i++) {
     if ((conns[i] != NULL) && (conns[i]->running == 0)) {
-      debug(3, "found RTSP connection thread %d in a non-running state.",
+      debug(4, "found RTSP connection thread %d in a non-running state.",
             conns[i]->connection_number);
       pthread_join(conns[i]->thread, &retval);
-      debug(3, "Connection %d: deleted in cleanup.", conns[i]->connection_number);
+      debug(4, "Connection %d: deleted in cleanup.", conns[i]->connection_number);
       free(conns[i]);
       conns[i] = NULL;
     }
     if (conns[i] != NULL) {
-      debug(3, "Airplay Volume for connection %d is %.6f.", conns[i]->connection_number,
+      debug(4, "Airplay Volume for connection %d is %.6f.", conns[i]->connection_number,
             suggested_volume(conns[i]));
       connection_count++;
     }
   }
-  debug_mutex_unlock(&conns_lock, 3);
+  debug_mutex_unlock(&conns_lock, 4);
 
   if (old_connection_count != connection_count) {
     if (connection_count == 0) {
-      debug(3, "No active connections.");
+      debug(4, "No active connections.");
     } else if (connection_count == 1)
-      debug(3, "One active connection.");
+      debug(4, "One active connection.");
     else
-      debug(3, "%d active connections.", connection_count);
+      debug(4, "%d active connections.", connection_count);
     old_connection_count = connection_count;
   }
-  debug(3, "Airplay Volume for new connections is %.6f.", suggested_volume(NULL));
+  debug(4, "Airplay Volume for new connections is %.6f.", suggested_volume(NULL));
 }
 
 // park a null at the line ending, and return the next line pointer
@@ -630,12 +630,12 @@ static char *nextline(char *in, int inbuf) {
 }
 
 void msg_retain(rtsp_message *msg) {
-  int rc = debug_mutex_lock(&reference_counter_lock, 500000, 1);
+  int rc = debug_mutex_lock(&reference_counter_lock, 500000, 4);
   if (rc)
     debug(1, "Error %d locking reference counter lock", rc);
   if (msg > (rtsp_message *)0x00010000) {
     msg->referenceCount++;
-    debug(3, "msg_free increment reference counter message %d to %d.", msg->index_number,
+    debug(4, "msg_free increment reference counter message %d to %d.", msg->index_number,
           msg->referenceCount);
     // debug(1,"msg_retain -- item %d reference count %d.", msg->index_number, msg->referenceCount);
     rc = pthread_mutex_unlock(&reference_counter_lock);
@@ -648,7 +648,7 @@ void msg_retain(rtsp_message *msg) {
 
 rtsp_message *msg_init(void) {
   // no thread cancellation points here
-  int rc = debug_mutex_lock(&reference_counter_lock, 500000, 1);
+  int rc = debug_mutex_lock(&reference_counter_lock, 500000, 4);
   if (rc)
     debug(1, "Error %d locking reference counter lock", rc);
 
@@ -657,7 +657,7 @@ rtsp_message *msg_init(void) {
     memset(msg, 0, sizeof(rtsp_message));
     msg->referenceCount = 1; // from now on, any access to this must be protected with the lock
     msg->index_number = msg_indexes++;
-    debug(3, "msg_init message %d", msg->index_number);
+    debug(4, "msg_init message %d", msg->index_number);
   } else {
     die("msg_init -- can not allocate memory for rtsp_message %d.", msg_indexes);
   }
@@ -731,7 +731,7 @@ void msg_free(rtsp_message **msgh) {
     rtsp_message *msg = *msgh;
     msg->referenceCount--;
     if (msg->referenceCount)
-      debug(3, "msg_free decrement reference counter message %d to %d", msg->index_number,
+      debug(4, "msg_free decrement reference counter message %d to %d", msg->index_number,
             msg->referenceCount);
     if (msg->referenceCount == 0) {
       unsigned int i;
@@ -747,7 +747,7 @@ void msg_free(rtsp_message **msgh) {
         index = 0x10000; // ensure it doesn't fold to zero.
       *msgh =
           (rtsp_message *)(index); // put a version of the index number of the freed message in here
-      debug(3, "msg_free freed message %d", msg->index_number);
+      debug(4, "msg_free freed message %d", msg->index_number);
       free(msg);
     } else {
       // debug(1,"msg_free item %d -- decrement reference to
@@ -771,7 +771,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) {
     char *sp, *p;
     sp = NULL; // this is to quieten a compiler warning
 
-    debug(3, "RTSP/HTTP Message Received: \"%s\".", line);
+    debug(4, "RTSP/HTTP Message Received: \"%s\".", line);
 
     p = strtok_r(line, " ", &sp);
     if (!p)
@@ -804,7 +804,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) {
     *p = 0;
     p += 2;
     msg_add_header(msg, line, p);
-    debug(3, "    %s: %s.", line, p);
+    debug(4, "    %s: %s.", line, p);
     return -1;
   } else {
     char *cl = msg_get_header(msg, "Content-Length");
@@ -1042,7 +1042,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes
     debug(1, "Connection %d: rtsp_read_request: can't get a buffer.", conn->connection_number);
     reply = rtsp_read_request_response_error;
   } else {
-    debug(3, "buf is allocated at 0x%" PRIxPTR ".", (uintptr_t)buf);
+    debug(4, "buf is allocated at 0x%" PRIxPTR ".", (uintptr_t)buf);
     pthread_cleanup_push(malloc_cleanup, &buf);
     ssize_t nread;
     ssize_t inbuf = 0;
@@ -1134,7 +1134,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes
           reply = rtsp_read_request_response_error;
           // goto shutdown;
         } else {
-          debug(3, "buf is reallocated at 0x%" PRIxPTR ".", (uintptr_t)buf);
+          debug(4, "buf is reallocated at 0x%" PRIxPTR ".", (uintptr_t)buf);
           buflen = msg_size;
         }
       }
@@ -1706,11 +1706,11 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
   if (messagePlist != NULL) {
     plist_t item = plist_dict_get_item(messagePlist, "flushFromSeq");
     if (item == NULL) {
-      debug(3, "Can't find a flushFromSeq");
+      debug(4, "Can't find a flushFromSeq");
     } else {
       flushFromValid = 1;
       plist_get_uint_val(item, &flushFromSeq);
-      debug(3, "flushFromSeq is %" PRId64 ".", flushFromSeq);
+      debug(3, "flushFromSeq is %" PRId64 ".", flushFromSeq & 0x7fffff);
     }
 
     item = plist_dict_get_item(messagePlist, "flushFromTS");
@@ -1718,7 +1718,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       if (flushFromValid != 0)
         debug(1, "flushFromSeq without flushFromTS!");
       else
-        debug(3, "Can't find a flushFromTS");
+        debug(4, "Can't find a flushFromTS");
     } else {
       plist_get_uint_val(item, &flushFromTS);
       if (flushFromValid == 0)
@@ -1731,7 +1731,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       debug(1, "Can't find the flushUntilSeq");
     } else {
       plist_get_uint_val(item, &flushUntilSeq);
-      debug(3, "flushUntilSeq is %" PRId64 ".", flushUntilSeq);
+      debug(4, "flushUntilSeq is %" PRId64 ".", flushUntilSeq & 0x7fffff);
     }
 
     item = plist_dict_get_item(messagePlist, "flushUntilTS");
@@ -1739,10 +1739,10 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       debug(1, "Can't find the flushUntilTS");
     } else {
       plist_get_uint_val(item, &flushUntilTS);
-      debug(3, "flushUntilTS is %" PRId64 ".", flushUntilTS);
+      debug(4, "flushUntilTS is %" PRId64 ".", flushUntilTS);
     }
 
-    debug_mutex_lock(&conn->flush_mutex, 1000, 1);
+    debug_mutex_lock(&conn->flush_mutex, 1000, 4);
 
     if (flushFromValid == 0) {
       // an immediate flush is requested
@@ -1782,7 +1782,7 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       }
     }
 
-    debug_mutex_unlock(&conn->flush_mutex, 3);
+    debug_mutex_unlock(&conn->flush_mutex, 4);
     plist_free(messagePlist);
   }
 
@@ -1860,7 +1860,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       uint64_t rate;
       plist_get_uint_val(item, &rate);
       debug(3, "anchor rate 0x%016" PRIx64 ".", rate);
-      pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 1000, 1);
+      pthread_cleanup_debug_mutex_lock(&conn->flush_mutex, 1000, 4);
       conn->ap2_rate = rate;
       if ((rate & 1) != 0) {
         ptp_send_control_message_string(
@@ -1874,6 +1874,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
 #endif
         conn->ap2_play_enabled = 1;
       } else {
+        reset_ptp_anchor_info(conn);
         ptp_send_control_message_string("P"); // signify play is "P"ausing
         debug(2, "Connection %d: SETRATEANCHORI Pause playing.", conn->connection_number);
         conn->ap2_play_enabled = 0;
@@ -2319,9 +2320,9 @@ void handle_configure(rtsp_conn_info *conn __attribute__((unused)),
 
 void handle_feedback(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req,
                      __attribute__((unused)) rtsp_message *resp) {
-  debug(3, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path,
+  debug(4, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path,
         req->contentlength);
-  debug_log_rtsp_message(3, NULL, req);
+  debug_log_rtsp_message(4, NULL, req);
 
   int is_playing = 0;
   int type = 0;
@@ -2361,7 +2362,7 @@ void handle_feedback(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message
     // plist_free(payload_plist);
 
     msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist");
-    debug_log_rtsp_message(3, "FEEDBACK response:", resp);
+    debug_log_rtsp_message(4, "FEEDBACK response:", resp);
   }
 }
 
@@ -2403,7 +2404,7 @@ void handle_command(rtsp_conn_info *conn, rtsp_message *req,
                     if (subsidiary_plist) {
                       char *printable_plist = plist_as_xml_text(subsidiary_plist);
                       if (printable_plist) {
-                        debug(3, "\n%s", printable_plist);
+                        debug(3, "Connection %d:\n==\n%s\n==", conn->connection_number, printable_plist);
                         free(printable_plist);
                       } else {
                         debug(1, "Can't print the plist!");
@@ -3857,13 +3858,13 @@ void *metadata_thread_function(__attribute__((unused)) void *ignore) {
     pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack);
     if (config.metadata_enabled) {
       if (pack.carrier) {
-        debug(3, "     pipe: type %x, code %x, length %u, message %d.", pack.type, pack.code,
+        debug(4, "     pipe: type %x, code %x, length %u, message %d.", pack.type, pack.code,
               pack.length, pack.carrier->index_number);
       } else {
-        debug(3, "     pipe: type %x, code %x, length %u.", pack.type, pack.code, pack.length);
+        debug(4, "     pipe: type %x, code %x, length %u.", pack.type, pack.code, pack.length);
       }
       metadata_process(pack.type, pack.code, pack.data, pack.length);
-      debug(3, "     pipe: done.");
+      debug(4, "     pipe: done.");
     }
     pthread_cleanup_pop(1);
   }
@@ -3887,18 +3888,18 @@ void *metadata_multicast_thread_function(__attribute__((unused)) void *ignore) {
     pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack);
     if (config.metadata_enabled) {
       if (pack.carrier) {
-        debug(3,
+        debug(4,
               "                                                                    multicast: type "
               "%x, code %x, length %u, message %d.",
               pack.type, pack.code, pack.length, pack.carrier->index_number);
       } else {
-        debug(3,
+        debug(4,
               "                                                                    multicast: type "
               "%x, code %x, length %u.",
               pack.type, pack.code, pack.length);
       }
       metadata_multicast_process(pack.type, pack.code, pack.data, pack.length);
-      debug(3,
+      debug(4,
             "                                                                    multicast: done.");
     }
     pthread_cleanup_pop(1);
@@ -3924,14 +3925,14 @@ void *metadata_hub_thread_function(__attribute__((unused)) void *ignore) {
     pc_queue_get_item(&metadata_hub_queue, &pack);
     pthread_cleanup_push(metadata_pack_cleanup_function, (void *)&pack);
     if (pack.carrier) {
-      debug(3, "                    hub: type %x, code %x, length %u, message %d.", pack.type,
+      debug(4, "                    hub: type %x, code %x, length %u, message %d.", pack.type,
             pack.code, pack.length, pack.carrier->index_number);
     } else {
-      debug(3, "                    hub: type %x, code %x, length %u.", pack.type, pack.code,
+      debug(4, "                    hub: type %x, code %x, length %u.", pack.type, pack.code,
             pack.length);
     }
     metadata_hub_process_metadata(pack.type, pack.code, pack.data, pack.length);
-    debug(3, "                    hub: done.");
+    debug(4, "                    hub: done.");
     pthread_cleanup_pop(1);
   }
   pthread_cleanup_pop(1); // will never happen
@@ -4222,7 +4223,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r
 }
 
 static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
-  debug(3, "Connection %d: SET_PARAMETER", conn->connection_number);
+  debug(4, "Connection %d: SET_PARAMETER", conn->connection_number);
   // if (!req->contentlength)
   //    debug(1, "received empty SET_PARAMETER request.");
 
@@ -4255,7 +4256,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m
     // not all items have RTP-time stuff in them, which is okay
 
     if (!strncmp(ct, "application/x-dmap-tagged", 25)) {
-      debug(3, "received metadata tags in SET_PARAMETER request.");
+      debug(4, "received metadata tags in SET_PARAMETER request.");
       if (p == NULL)
         debug(1, "Missing RTP-Time info for metadata");
       if (p)
@@ -5018,7 +5019,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) {
 }
 
 void msg_cleanup_function(void *arg) {
-  debug(3, "msg_cleanup_function called 0x%" PRIxPTR ".", (uintptr_t)arg);
+  debug(4, "msg_cleanup_function called 0x%" PRIxPTR ".", (uintptr_t)arg);
   msg_free((rtsp_message **)arg);
 }
 
@@ -5063,18 +5064,18 @@ static void *rtsp_conversation_thread_func(void *pconn) {
 
   while (conn->stop == 0) {
     pthread_testcancel();
-    int debug_level = 2; // for printing the request and response
+    int debug_level = 4; // for printing the request and response
 
     // check to see if a conn has been zeroed
 
-    debug_mutex_lock(&conns_lock, 1000000, 3);
+    debug_mutex_lock(&conns_lock, 1000000, 4);
     int i;
     for (i = 0; i < nconns; i++) {
       if ((conns[i] != NULL) && (conns[i]->connection_number == 0)) {
         debug(1, "conns[%d] has a Connection Number of 0!", i);
       }
     }
-    debug_mutex_unlock(&conns_lock, 3);
+    debug_mutex_unlock(&conns_lock, 4);
 
     reply = rtsp_read_request(conn, &req);
     if (reply == rtsp_read_request_response_ok) {

shairport-sync-dbus-test-client.c

@@ -68,7 +68,7 @@ void on_properties_changed(__attribute__((unused)) GDBusProxy *proxy, GVariant *
 void notify_loudness_callback(ShairportSync *proxy, __attribute__((unused)) gpointer user_data) {
   //  printf("\"notify_loudness_callback\" called with a gpointer of
   //  %lx.\n",(int64_t)user_data);
-  gboolean ebl = shairport_sync_get_loudness(proxy);
+  gboolean ebl = shairport_sync_get_loudness_enabled(proxy);
   if (ebl == TRUE)
     printf("Client reports loudness is enabled.\n");
   else

utilities/buffered_read.c

@@ -34,7 +34,7 @@
 ssize_t buffered_read(buffered_tcp_desc *descriptor, void *buf, size_t count,
                       size_t *bytes_remaining) {
   ssize_t response = -1;
-  if (debug_mutex_lock(&descriptor->mutex, 50000, 1) != 0)
+  if (debug_mutex_lock(&descriptor->mutex, 50000, 4) != 0)
     debug(1, "problem with mutex");
   pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex);
   // wipe the slate dlean before reading...
@@ -115,7 +115,7 @@ void *buffered_tcp_reader(void *arg) {
 
   do {
     int have_time_to_sleep = 0;
-    if (debug_mutex_lock(&descriptor->mutex, 500000, 1) != 0)
+    if (debug_mutex_lock(&descriptor->mutex, 500000, 4) != 0)
       debug(1, "problem with mutex");
     pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex);
     while (descriptor->buffer_occupancy == descriptor->buffer_max_size) {
@@ -148,7 +148,7 @@ void *buffered_tcp_reader(void *arg) {
     nread = recv(fd, descriptor->eoq, bytes_to_request, 0);
     // debug(1, "Received %d bytes for a buffer size of %d bytes.",nread,
     // descriptor->buffer_occupancy + nread);
-    if (debug_mutex_lock(&descriptor->mutex, 50000, 1) != 0)
+    if (debug_mutex_lock(&descriptor->mutex, 50000, 4) != 0)
       debug(1, "problem with not empty mutex");
     pthread_cleanup_push(mutex_unlock, (void *)&descriptor->mutex);
     if (nread < 0) {

utilities/debug.c

@@ -196,7 +196,7 @@ void _debug(const char *filename, const int linenumber, int level, const char *f
     return;
   int oldState;
   pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState);
-  char b[1024];
+  char b[1024 * 64];
   b[0] = 0;
   pthread_mutex_lock(&debug_timing_lock);
   uint64_t time_now = debug_get_absolute_time_in_ns();
@@ -255,18 +255,18 @@ void _debug_print_buffer(const char *thefilename, const int linenumber, int leve
     char *obfp = obf;
     unsigned int obfc;
     for (obfc = 0; obfc < buf_len; obfc++) {
-      snprintf(obfp, 3, "%02X", buf[obfc]);
+      snprintf(obfp, 3, "%02X", (unsigned char)buf[obfc]);
       obfp += 2;
       if (obfc != buf_len - 1) {
         if (obfc % 32 == 31) {
           snprintf(obfp, 5, " || ");
-          obfp += 4;
+          obfp += strlen(" || ");
         } else if (obfc % 16 == 15) {
           snprintf(obfp, 4, " | ");
-          obfp += 3;
+          obfp += strlen(" | ");;
         } else if (obfc % 4 == 3) {
           snprintf(obfp, 2, " ");
-          obfp += 1;
+          obfp += strlen(" ");;
         }
       }
     };