chiark / gitweb /
dotlock.c: add a lot of debug logging
authorIan Jackson <ijackson@chiark.greenend.org.uk>
Sun, 8 Jan 2017 16:40:21 +0000 (16:40 +0000)
committerIan Jackson <ijackson@chiark.greenend.org.uk>
Sun, 8 Jan 2017 20:43:03 +0000 (20:43 +0000)
This doesn't seem to be sensibly controllable other than at compile
time because the relevant logging control variables are not available.
I hope upstream will be able to improve that.

Signed-off-by: Ian Jackson <ijackson@chiark.greenend.org.uk>
common/dotlock.c

index 7ebd523..037125a 100644 (file)
@@ -471,6 +471,18 @@ map_w32_to_errno (DWORD w32_err)
 }
 #endif /*HAVE_DOSISH_SYSTEM*/
 
+#define DLOG(h, m, ...) do{                            \
+    dotlock_t DLOG_h = (h);                            \
+    int DLOG_se = errno;                               \
+    if (/*DBG_IPC*/ 0)                                 \
+      log_debug("dotlock %p %s " m, (DLOG_h),          \
+               !(DLOG_h)           ? "(none)" :        \
+               !(DLOG_h)->lockname ? "(null)" :        \
+                (DLOG_h)->lockname,                    \
+               ##__VA_ARGS__);                         \
+    errno = DLOG_se;                                   \
+  }while(0)
+
 \f
 /* Entirely disable all locking.  This function should be called
    before any locking is done.  It may be called right at startup of
@@ -478,6 +490,7 @@ map_w32_to_errno (DWORD w32_err)
 void
 dotlock_disable (void)
 {
+  DLOG(0, "dotlock_disable\n");
   never_lock = 1;
 }
 
@@ -489,6 +502,8 @@ maybe_deadlock (dotlock_t h)
   dotlock_t r;
   int res = 0;
 
+  DLOG(h, "maybe_deadlock\n");
+
   LOCK_all_lockfiles ();
   for (r=all_lockfiles; r; r = r->next)
     {
@@ -519,6 +534,8 @@ read_lockfile (dotlock_t h, int *same_node )
   size_t expected_len;
   int res, nread;
 
+  DLOG(h, "read_lockfile()\n");
+
   *same_node = 0;
   expected_len = 10 + 1 + h->nodename_len + 1;
   if ( expected_len >= sizeof buffer_space)
@@ -591,6 +608,7 @@ read_lockfile (dotlock_t h, int *same_node )
 
   if (buffer != buffer_space)
     xfree (buffer);
+  DLOG(h, "read_lockfile(%d) = %ld\n", *same_node, (long)pid);
   return pid;
 }
 #endif /*HAVE_POSIX_SYSTEM */
@@ -610,6 +628,8 @@ use_hardlinks_p (const char *tname)
   unsigned int nlink;
   int res;
 
+  DLOG(0, "use_hardlinks_p(%s)\n", tname);
+
   if (stat (tname, &sb))
     return -1;
   nlink = (unsigned int)sb.st_nlink;
@@ -632,6 +652,8 @@ use_hardlinks_p (const char *tname)
 
   unlink (lname);
   xfree (lname);
+
+  DLOG(0, "use_hardlinks_p(%s) = %d\n", tname, res);
   return res;
 }
 #endif /*HAVE_POSIX_SYSTEM */
@@ -652,6 +674,8 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
   struct utsname utsbuf;
   size_t tnamelen;
 
+  DLOG(h, "dotlock_create_unix(%s)...\n", file_to_lock);
+
   snprintf (pidstr, sizeof pidstr, "%10d\n", (int)getpid() );
 
   /* Create a temporary file. */
@@ -682,6 +706,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
       all_lockfiles = h->next;
       UNLOCK_all_lockfiles ();
       xfree (h);
+      DLOG(h, "dotlock_create_unix()=0 (!xtrymalloc)\n");
       return NULL;
     }
   h->nodename_len = strlen (nodename);
@@ -691,6 +716,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
   snprintf (h->tname+h->nodename_off, tnamelen - h->nodename_off,
            "%s.%d", nodename, (int)getpid ());
 
+  DLOG(h, "dotlock_create_unix() open...\n");
   do
     {
       my_set_errno (0);
@@ -698,6 +724,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
                  S_IRUSR|S_IRGRP|S_IROTH|S_IWUSR );
     }
   while (fd == -1 && errno == EINTR);
+  DLOG(h, "dotlock_create_unix() open=%d...\n", fd);
 
   if ( fd == -1 )
     {
@@ -709,6 +736,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
       xfree (h->tname);
       xfree (h);
       my_set_errno (saveerrno);
+      DLOG(h, "dotlock_create_unix()=0 (fd=-1) E=%d\n",errno);
       return NULL;
     }
   if ( write (fd, pidstr, 11 ) != 11 )
@@ -754,6 +782,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
       xfree (h->tname);
       xfree (h);
       my_set_errno (saveerrno);
+      DLOG(h, "dotlock_create_unix()=0 (!lockname) E=%d\n",errno);
       return NULL;
     }
   strcpy (stpcpy (h->lockname, file_to_lock), EXTSEP_S "lock");
@@ -761,6 +790,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
   if (h->use_o_excl)
     my_debug_1 ("locking for '%s' done via O_EXCL\n", h->lockname);
 
+  DLOG(h, "dotlock_create_unix()=%p\n", h);
   return h;
 
  write_failed:
@@ -776,6 +806,7 @@ dotlock_create_unix (dotlock_t h, const char *file_to_lock)
     xfree (h);
     my_set_errno (saveerrno);
   }
+  DLOG(h, "dotlock_create_unix()=0 (write_failed) E=%d\n",errno);
   return NULL;
 }
 #endif /*HAVE_POSIX_SYSTEM*/
@@ -936,6 +967,10 @@ dotlock_get_fd (dotlock_t h)
 static void
 dotlock_destroy_unix (dotlock_t h)
 {
+  DLOG(h, "dotlock_destroy_unix() locked=%d lockname=%s tname=%s\n",
+       h->locked,
+       h->lockname ? h->lockname : "(null)",
+       h->tname ? h->tname : "(null)");
   if (h->locked && h->lockname)
     unlink (h->lockname);
   if (h->tname && !h->use_o_excl)
@@ -968,6 +1003,7 @@ dotlock_destroy (dotlock_t h)
 {
   dotlock_t hprev, htmp;
 
+  DLOG(h, "dotlock_destroy()\n");
   if ( !h )
     return;
 
@@ -1015,12 +1051,15 @@ dotlock_take_unix (dotlock_t h, long timeout)
   int same_node;
   int saveerrno;
 
+  DLOG(h, "dotlock_create_unix(timeout=%ld) ...\n", timeout);
+
  again:
   if (h->use_o_excl)
     {
       /* No hardlink support - use open(O_EXCL).  */
       int fd;
 
+      DLOG(h, "dotlock_take_unix() open...\n");
       do
         {
           my_set_errno (0);
@@ -1028,6 +1067,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
                      S_IRUSR|S_IRGRP|S_IROTH|S_IWUSR );
         }
       while (fd == -1 && errno == EINTR);
+      DLOG(h, "dotlock_take_unix() open=%d E=%d...\n",fd,errno);
 
       if (fd == -1 && errno == EEXIST)
         ; /* Lock held by another process.  */
@@ -1037,6 +1077,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
           my_error_2 ("lock not made: open(O_EXCL) of '%s' failed: %s\n",
                       h->lockname, strerror (saveerrno));
           my_set_errno (saveerrno);
+         DLOG(h, "dotlock_take_unix()=-1 (fd=-1) E=%d\n",errno);
           return -1;
         }
       else
@@ -1051,6 +1092,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
               && !close (fd))
             {
               h->locked = 1;
+             DLOG(h, "dotlock_take_unix()=0 (write)\n");
               return 0;
             }
           /* Write error.  */
@@ -1060,6 +1102,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
           close (fd);
           unlink (h->lockname);
           my_set_errno (saveerrno);
+         DLOG(h, "dotlock_take_unix()=-1 (write) E=%d\n",errno);
           return -1;
         }
     }
@@ -1079,12 +1122,14 @@ dotlock_take_unix (dotlock_t h, long timeout)
              that link succeeded but stat failed due to changed
              permissions.  We can't do anything about it, though.  */
           my_set_errno (saveerrno);
+         DLOG(h, "dotlock_take_unix()=-1 (stat) E=%d\n",errno);
           return -1;
         }
 
       if (sb.st_nlink == 2)
         {
           h->locked = 1;
+         DLOG(h, "dotlock_take_unix()=0 (nlink)\n");
           return 0; /* Okay.  */
         }
     }
@@ -1097,6 +1142,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
           saveerrno = errno;
           my_info_0 ("cannot read lockfile\n");
           my_set_errno (saveerrno);
+         DLOG(h, "dotlock_take_unix()=-1 (read) E=%d\n",errno);
           return -1;
         }
       my_info_0 ("lockfile disappeared\n");
@@ -1106,6 +1152,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
     {
       my_info_0 ("Oops: lock already held by us\n");
       h->locked = 1;
+      DLOG(h, "dotlock_take_unix()=0 (oops)\n");
       return 0; /* okay */
     }
   else if ( same_node && kill (pid, 0) && errno == ESRCH )
@@ -1115,6 +1162,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
          of the stale file tries to lock right at the same time as we.  */
       my_info_1 (_("removing stale lockfile (created by %d)\n"), pid);
       unlink (h->lockname);
+      DLOG(h, "dotlock_take_unix() again...\n");
       goto again;
     }
 
@@ -1161,6 +1209,7 @@ dotlock_take_unix (dotlock_t h, long timeout)
     }
 
   my_set_errno (EACCES);
+  DLOG(h, "dotlock_take_unix()=-1 (EACCES) E=%d\n",errno);
   return -1;
 }
 #endif /*HAVE_POSIX_SYSTEM*/
@@ -1264,18 +1313,22 @@ dotlock_release_unix (dotlock_t h)
   int pid, same_node;
   int saveerrno;
 
+  DLOG(h, "dotlock_release_unix...\n");
+
   pid = read_lockfile (h, &same_node);
   if ( pid == -1 )
     {
       saveerrno = errno;
       my_error_0 ("release_dotlock: lockfile error\n");
       my_set_errno (saveerrno);
+      DLOG(h, "dotlock_release_unix()=-1 (read) E=%d\n",errno);
       return -1;
     }
   if ( pid != getpid() || !same_node )
     {
       my_error_1 ("release_dotlock: not our lock (pid=%d)\n", pid);
       my_set_errno (EACCES);
+      DLOG(h, "dotlock_release_unix()=-1 (not ours) E=%d\n",errno);
       return -1;
     }
 
@@ -1285,10 +1338,12 @@ dotlock_release_unix (dotlock_t h)
       my_error_1 ("release_dotlock: error removing lockfile '%s'\n",
                   h->lockname);
       my_set_errno (saveerrno);
+      DLOG(h, "dotlock_release_unix()=-1 (unlink) E=%d\n",errno);
       return -1;
     }
   /* Fixme: As an extra check we could check whether the link count is
      now really at 1. */
+  DLOG(h, "dotlock_release_unix()=0\n");
   return 0;
 }
 #endif /*HAVE_POSIX_SYSTEM */
@@ -1321,6 +1376,7 @@ int
 dotlock_release (dotlock_t h)
 {
   int ret;
+  DLOG(h, "dotlock_release\n");
 
   /* To avoid atexit race conditions we first check whether there are
      any locks left.  It might happen that another atexit handler
@@ -1361,10 +1417,12 @@ void
 dotlock_remove_lockfiles (void)
 {
   dotlock_t h, h2;
+  DLOG(0, "dotlock_remove_lockfiles\n");
 
   /* First set the lockfiles list to NULL so that for example
      dotlock_release is aware that this function is currently
      running.  */
+
   LOCK_all_lockfiles ();
   h = all_lockfiles;
   all_lockfiles = NULL;