From: Mike Brady <mikebrady@eircom.net>
Date: Fri, 1 Jun 2018 08:28:28 +0000 (+0100)
Subject: Add debug_mutex_unlock code in place of a regular pthread_mutex_unlock in some places.
X-Git-Tag: 3.2RC11~3^2~19
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=93f410599f79f1ddbed75b44f1cf7c59aeb83fcc;p=thirdparty%2Fshairport-sync.git

Add debug_mutex_unlock code in place of a regular pthread_mutex_unlock in some places.
---

diff --git a/audio_alsa.c b/audio_alsa.c
index b1e4d1f8..e2a53ccd 100644
--- a/audio_alsa.c
+++ b/audio_alsa.c
@@ -219,7 +219,7 @@ static int init(int argc, char **argv) {
       else if (strcasecmp(str, "yes") == 0)
         config.no_sync = 1;
       else {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid disable_synchronization option choice \"%s\". It should be \"yes\" or \"no\"");
       }
     }
@@ -233,7 +233,7 @@ static int init(int argc, char **argv) {
       else if (strcasecmp(str, "yes") == 0)
         config.alsa_use_hardware_mute = 1;
       else {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid mute_using_playback_switch option choice \"%s\". It should be \"yes\" or "
             "\"no\"");
       }
@@ -246,7 +246,7 @@ static int init(int argc, char **argv) {
       else if (strcasecmp(str, "yes") == 0)
         config.alsa_use_hardware_mute = 1;
       else {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid use_hardware_mute_if_available option choice \"%s\". It should be \"yes\" or "
             "\"no\"");
       }
@@ -269,7 +269,7 @@ static int init(int argc, char **argv) {
       else if (strcasecmp(str, "S8") == 0)
         config.output_format = SPS_FORMAT_S8;
       else {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid output format \"%s\". It should be \"U8\", \"S8\", \"S16\", \"S24\", "
             "\"S24_3LE\", \"S24_3BE\" or "
             "\"S32\"",
@@ -288,7 +288,7 @@ static int init(int argc, char **argv) {
         config.output_rate = value;
         break;
       default:
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid output rate \"%d\". It should be a multiple of 44,100 up to 352,800", value);
       }
     }
@@ -300,7 +300,7 @@ static int init(int argc, char **argv) {
       else if (strcasecmp(str, "yes") == 0)
         config.no_mmap = 0;
       else {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid use_mmap_if_available option choice \"%s\". It should be \"yes\" or \"no\"");
       }
     }
@@ -309,7 +309,7 @@ static int init(int argc, char **argv) {
       set_period_size_request = 1;
       debug(1, "Value read for period size is %d.", value);
       if (value < 0) {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid alsa period size setting \"%d\". It "
             "must be greater than 0.",
             value);
@@ -323,7 +323,7 @@ static int init(int argc, char **argv) {
       set_buffer_size_request = 1;
       debug(1, "Value read for buffer size is %d.", value);
       if (value < 0) {
-        pthread_mutex_unlock(&alsa_mutex);
+        debug_mutex_unlock(&alsa_mutex, 3);
         die("Invalid alsa buffer size setting \"%d\". It "
             "must be greater than 0.",
             value);
@@ -362,13 +362,13 @@ static int init(int argc, char **argv) {
       break;
     default:
       help();
-      pthread_mutex_unlock(&alsa_mutex);
+      debug_mutex_unlock(&alsa_mutex, 3);
       die("Invalid audio option -%c specified", opt);
     }
   }
 
   if (optind < argc) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("Invalid audio argument: %s", argv[optind]);
   }
 
@@ -412,11 +412,11 @@ static int init(int argc, char **argv) {
               alsa_mix_ctrl);
 
         if (snd_ctl_open(&ctl, alsa_mix_dev, 0) < 0) {
-          pthread_mutex_unlock(&alsa_mutex);
+          debug_mutex_unlock(&alsa_mutex, 3);
           die("Cannot open control \"%s\"", alsa_mix_dev);
         }
         if (snd_ctl_elem_id_malloc(&elem_id) < 0) {
-          pthread_mutex_unlock(&alsa_mutex);
+          debug_mutex_unlock(&alsa_mutex, 3);
           die("Cannot allocate memory for control \"%s\"", alsa_mix_dev);
         }
         snd_ctl_elem_id_set_interface(elem_id, SND_CTL_ELEM_IFACE_MIXER);
@@ -462,7 +462,7 @@ static int init(int argc, char **argv) {
   }
 
   alsa_mix_handle = NULL;
-  pthread_mutex_unlock(&alsa_mutex);
+  debug_mutex_unlock(&alsa_mutex, 3);
   return 0;
 }
 
@@ -507,7 +507,7 @@ int open_alsa_device(void) {
 
   ret = snd_pcm_hw_params_any(alsa_handle, alsa_params);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     ;
     die("audio_alsa: Broken configuration for device \"%s\": no configurations "
         "available",
@@ -534,7 +534,7 @@ int open_alsa_device(void) {
 
   ret = snd_pcm_hw_params_set_access(alsa_handle, alsa_params, access);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("audio_alsa: Access type not available for device \"%s\": %s", alsa_out_dev,
         snd_strerror(ret));
   }
@@ -562,20 +562,20 @@ int open_alsa_device(void) {
     sf = SND_PCM_FORMAT_S32;
     break;
   default:
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     sf = SND_PCM_FORMAT_S16; // this is just to quieten a compiler warning
     die("Unsupported output format at audio_alsa.c");
   }
   ret = snd_pcm_hw_params_set_format(alsa_handle, alsa_params, sf);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("audio_alsa: Sample format %d not available for device \"%s\": %s", sample_format,
         alsa_out_dev, snd_strerror(ret));
   }
 
   ret = snd_pcm_hw_params_set_channels(alsa_handle, alsa_params, 2);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("audio_alsa: Channels count (2) not available for device \"%s\": %s", alsa_out_dev,
         snd_strerror(ret));
   }
@@ -591,7 +591,7 @@ int open_alsa_device(void) {
     ret = snd_pcm_hw_params_set_period_size_near(alsa_handle, alsa_params, &period_size_requested,
                                                  &dir);
     if (ret < 0) {
-      pthread_mutex_unlock(&alsa_mutex);
+      debug_mutex_unlock(&alsa_mutex, 3);
       die("audio_alsa: cannot set period size of %lu: %s", period_size_requested,
           snd_strerror(ret));
       snd_pcm_uframes_t actual_period_size;
@@ -607,7 +607,7 @@ int open_alsa_device(void) {
     debug(1, "Attempting to set the buffer size to %lu", buffer_size_requested);
     ret = snd_pcm_hw_params_set_buffer_size_near(alsa_handle, alsa_params, &buffer_size_requested);
     if (ret < 0) {
-      pthread_mutex_unlock(&alsa_mutex);
+      debug_mutex_unlock(&alsa_mutex, 3);
       die("audio_alsa: cannot set buffer size of %lu: %s", buffer_size_requested,
           snd_strerror(ret));
     }
@@ -621,19 +621,19 @@ int open_alsa_device(void) {
 
   ret = snd_pcm_hw_params(alsa_handle, alsa_params);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("audio_alsa: Unable to set hw parameters for device \"%s\": %s.", alsa_out_dev,
         snd_strerror(ret));
   }
 
   if (my_sample_rate != desired_sample_rate) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("Can't set the D/A converter to %d.", desired_sample_rate);
   }
 
   ret = snd_pcm_hw_params_get_buffer_size(alsa_params, &actual_buffer_length);
   if (ret < 0) {
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     die("audio_alsa: Unable to get hw buffer length for device \"%s\": %s.", alsa_out_dev,
         snd_strerror(ret));
   }
@@ -843,7 +843,7 @@ int delay(long *the_delay) {
         debug(1, "Error preparing after delay error: \"%s\".", snd_strerror(derr));
       }
     }
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
     // here, occasionally pretend there's a problem with pcm_get_delay()
     // if ((random() % 100000) < 3) // keep it pretty rare
     //	reply = -EPERM; // pretend something bad has happened
@@ -863,7 +863,7 @@ static void play(void *buf, int samples) {
       if (audio_alsa.mute)
         do_mute(0);
     }
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
   }
   if (ret == 0) {
     debug_mutex_lock(&alsa_mutex, 10000, 1);
@@ -897,7 +897,7 @@ static void play(void *buf, int samples) {
         debug(1, "Error preparing after play error: \"%s\".", snd_strerror(err));
       }
     }
-    pthread_mutex_unlock(&alsa_mutex);
+    debug_mutex_unlock(&alsa_mutex, 3);
   }
 }
 
@@ -920,7 +920,7 @@ static void flush(void) {
 
     alsa_handle = NULL;
   }
-  pthread_mutex_unlock(&alsa_mutex);
+  debug_mutex_unlock(&alsa_mutex, 3);
 }
 
 static void stop(void) {
@@ -976,7 +976,7 @@ void volume(double vol) {
   debug_mutex_lock(&alsa_mutex, 1000, 1);
   volume_set_request = 1; // an external request has been made to set the volume
   do_volume(vol);
-  pthread_mutex_unlock(&alsa_mutex);
+  debug_mutex_unlock(&alsa_mutex, 3);
 }
 
 /*
@@ -1003,7 +1003,7 @@ static void mute(int mute_state_requested) {
   mute_request_pending = 1;
   overriding_mute_state_requested = mute_state_requested;
   do_mute(mute_state_requested);
-  pthread_mutex_unlock(&alsa_mutex);
+  debug_mutex_unlock(&alsa_mutex, 3);
 }
 
 void do_mute(int mute_state_requested) {
diff --git a/common.c b/common.c
index 41218609..da2db747 100644
--- a/common.c
+++ b/common.c
@@ -1042,13 +1042,28 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char
                       const int line, int debuglevel) {
   char dstring[1000];
   memset(dstring, 0, sizeof(dstring));
-  snprintf(dstring, sizeof(dstring), "%s%d", filename, line);
+  snprintf(dstring, sizeof(dstring), "%s:%d", filename, line);
+  debug(3, "debug_mutex_lock at \"%s\".", dstring);
   int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel);
   if (result == EBUSY)
     result = pthread_mutex_lock(mutex);
   return result;
 }
 
+int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line,
+                        int debuglevel) {
+  char dstring[1000];
+  char errstr[512];
+  memset(dstring, 0, sizeof(dstring));
+  snprintf(dstring, sizeof(dstring), "%s:%d", filename, line);
+  debug(debuglevel, "debug_mutex_unlock at \"%s\".", dstring);
+  int r = pthread_mutex_unlock(mutex);
+  if (r != 0)
+    debug(1, "error %d: \"%s\" unlocking a mutex: \"%s\".", r,
+          strerror_r(r, errstr, sizeof(errstr)), dstring);
+  return r;
+}
+
 char *get_version_string() {
   char *version_string = malloc(200);
   if (version_string) {
diff --git a/common.h b/common.h
index 8878c390..87493cb1 100644
--- a/common.h
+++ b/common.h
@@ -271,6 +271,11 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char
 
 #define debug_mutex_lock(mu, t, d) _debug_mutex_lock(mu, t, __FILE__, __LINE__, d)
 
+int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line,
+                        int debuglevel);
+
+#define debug_mutex_unlock(mu, d) _debug_mutex_unlock(mu, __FILE__, __LINE__, d)
+
 char *get_version_string(); // mallocs a string space -- remember to free it afterwards
 
 void sps_nanosleep(const time_t sec,
diff --git a/player.c b/player.c
index e7767e4a..7fbc45d5 100644
--- a/player.c
+++ b/player.c
@@ -481,10 +481,10 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
         debug_mutex_lock(&conn->flush_mutex, 1000, 1);
         conn->flush_requested = 0;
         conn->flush_rtp_timestamp = 0;
-        pthread_mutex_unlock(&conn->flush_mutex);
+        debug_mutex_unlock(&conn->flush_mutex, 3);
       }
 
-      debug_mutex_lock(&conn->ab_mutex, 10000, 1);
+      debug_mutex_lock(&conn->ab_mutex, 40000, 1);
       conn->packet_count++;
       conn->time_of_last_audio_packet = get_absolute_time_in_fp();
       if (conn->connection_state_to_output) { // if we are supposed to be processing these packets
@@ -626,7 +626,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
         if (rc)
           debug(1, "Error signalling flowcontrol.");
       }
-      pthread_mutex_unlock(&conn->ab_mutex);
+      debug_mutex_unlock(&conn->ab_mutex, 3);
     } else {
       debug(
           1,
@@ -787,7 +787,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
   abuf_t *curframe = 0;
   int notified_buffer_empty = 0; // diagnostic only
 
-  debug_mutex_lock(&conn->ab_mutex, 10000, 1);
+  debug_mutex_lock(&conn->ab_mutex, 40000, 1);
   int wait;
   long dac_delay = 0; // long because alsa returns a long
   do {
@@ -819,7 +819,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
       if (conn->connection_state_to_output == 0) { // going off
         debug_mutex_lock(&conn->flush_mutex, 1000, 1);
         conn->flush_requested = 1;
-        pthread_mutex_unlock(&conn->flush_mutex);
+        debug_mutex_unlock(&conn->flush_mutex, 3);
       }
     }
 
@@ -833,7 +833,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
       conn->time_since_play_started = 0;
       conn->flush_requested = 0;
     }
-    pthread_mutex_unlock(&conn->flush_mutex);
+    debug_mutex_unlock(&conn->flush_mutex, 3);
 
     uint32_t flush_limit = 0;
     if (conn->ab_synced) {
@@ -1232,7 +1232,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
 
   if (conn->player_thread_please_stop) {
     debug(3, "buffer_get_frame exiting due to thread stop request.");
-    pthread_mutex_unlock(&conn->ab_mutex);
+    debug_mutex_unlock(&conn->ab_mutex, 3);
     return 0;
   }
 
@@ -1246,7 +1246,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
   curframe->ready = 0;
   curframe->resend_level = 0;
   conn->ab_read = SUCCESSOR(conn->ab_read);
-  pthread_mutex_unlock(&conn->ab_mutex);
+  debug_mutex_unlock(&conn->ab_mutex, 3);
   return curframe;
 }
 
@@ -1324,7 +1324,7 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l
       process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn);
     }
   }
-  pthread_mutex_unlock(&conn->vol_mutex);
+  debug_mutex_unlock(&conn->vol_mutex, 3);
   conn->amountStuffed = tstuff;
   return length + tstuff;
 }
@@ -2584,7 +2584,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
 
   debug_mutex_lock(&conn->vol_mutex, 1000, 1);
   conn->fix_volume = temp_fix_volume;
-  pthread_mutex_unlock(&conn->vol_mutex);
+  debug_mutex_unlock(&conn->vol_mutex, 3);
 
   if (config.loudness)
     loudness_set_volume(software_attenuation / 100);
@@ -2621,7 +2621,7 @@ void do_flush(int64_t timestamp, rtsp_conn_info *conn) {
   conn->flush_requested = 1;
   // if (timestamp!=0)
   conn->flush_rtp_timestamp = timestamp; // flush all packets up to (and including?) this
-  pthread_mutex_unlock(&conn->flush_mutex);
+  debug_mutex_unlock(&conn->flush_mutex, 3);
   conn->play_segment_reference_frame = 0;
   conn->play_number_after_flush = 0;
 #ifdef CONFIG_METADATA
diff --git a/rtp.c b/rtp.c
index 01f71c3f..e7ac0dbd 100644
--- a/rtp.c
+++ b/rtp.c
@@ -339,7 +339,7 @@ void *rtp_control_receiver(void *arg) {
                 remote_time_of_sync - conn->local_to_remote_time_difference;
             conn->reference_timestamp = sync_rtp_timestamp;
             conn->latency_delayed_timestamp = rtp_timestamp_less_latency;
-            pthread_mutex_unlock(&conn->reference_time_mutex);
+            debug_mutex_unlock(&conn->reference_time_mutex, 3);
 
             // this is for debugging
             /*
@@ -898,14 +898,14 @@ void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time,
   //  debug(1,"Reference timestamp is invalid.");
   //}
   *remote_timestamp_time = conn->remote_reference_timestamp_time;
-  pthread_mutex_unlock(&conn->reference_time_mutex);
+  debug_mutex_unlock(&conn->reference_time_mutex, 3);
 }
 
 void clear_reference_timestamp(rtsp_conn_info *conn) {
   debug_mutex_lock(&conn->reference_time_mutex, 1000, 1);
   conn->reference_timestamp = 0;
   conn->reference_timestamp_time = 0;
-  pthread_mutex_unlock(&conn->reference_time_mutex);
+  debug_mutex_unlock(&conn->reference_time_mutex, 3);
 }
 
 void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) {