From c8b9729922b84ced5cd7071a16e62860064dda88 Mon Sep 17 00:00:00 2001 From: Ian Jackson Date: Sun, 8 Jan 2017 16:40:21 +0000 Subject: [PATCH] dotlock.c: add a lot of debug logging 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 --- common/dotlock.c | 58 ++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/common/dotlock.c b/common/dotlock.c index 7ebd523..037125a 100644 --- a/common/dotlock.c +++ b/common/dotlock.c @@ -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) + /* 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; -- 2.30.2