Use libbacktrace to debug file locking issues

dscho · dscho · commit 6866f7fc2051 · 2017-11-19T22:04:45.000+01:00
On Windows, it is not possible to overwrite files as long as they are in
use. This is particularly funny (not!) when the same process still holds
open file handles to that file, and it notoriously hard to debug.

Let's add a compile-time option to output stacktraces to the offending
calls when we fail to overwrite/remove them.

Note: it has to be a compile time option because we would have to turn
off ASLR otherwise (and it is too good of a first line of defense to
just turn off).

Signed-off-by: Johannes Schindelin &lt;johannes.schindelin@gmx.de&gt;
diff --git a/compat/mingw.c b/compat/mingw.c
@@ -11,6 +11,175 @@
 #include "../config.h"
 #include "../string-list.h"
 
+#ifdef DEBUG_FILE_LOCKS
+
+#include "libbacktrace/backtrace.h"
+#include "../hashmap.h"
+
+struct file_lock_backtrace
+{
+	struct hashmap_entry entry;
+	int fd, count;
+	uintptr_t *pcs;
+	const char *filename;
+};
+
+static CRITICAL_SECTION backtrace_mutex;
+static struct hashmap file_lock_map;
+#define FILE_LOCK_MAX_FD 256
+static struct file_lock_backtrace *file_lock_by_fd[FILE_LOCK_MAX_FD];
+
+static int my_backtrace_cb(void *data, uintptr_t pc, const char *filename,
+			   int lineno, const char *function)
+{
+	struct strbuf *buf = data;
+
+	if (!function || !strcmp("__tmainCRTStartup", function))
+		return -1;
+
+	strbuf_addf(buf, "%s:%d:\n\t%s\n", filename, lineno, function);
+
+	return 0;
+}
+
+static void my_error_cb(void *data, const char *msg, int errnum)
+{
+	struct strbuf *buf = data;
+
+	strbuf_addf(buf, "error %s (%d)\n", msg, errnum);
+}
+
+static void file_lock_backtrace(struct file_lock_backtrace *data,
+				struct strbuf *buf)
+{
+	static struct backtrace_state *state;
+	static int initialized;
+	int i;
+
+	if (!initialized) {
+		EnterCriticalSection(&backtrace_mutex);
+		if (!initialized) {
+			state = backtrace_create_state(NULL, 1, my_error_cb,
+						       NULL);
+			initialized = 1;
+		}
+		LeaveCriticalSection(&backtrace_mutex);
+	}
+
+	if (data->fd >= 0)
+		strbuf_addf(buf, "file '%s' (fd %d) was opened here:\n",
+			    data->filename, data->fd);
+	for (i = 0; i < data->count; i++)
+		if (backtrace_pcinfo(state, data->pcs[i], my_backtrace_cb,
+				     my_error_cb, buf) < 0)
+			break;
+}
+
+static struct file_lock_backtrace *alloc_file_lock_backtrace(int fd,
+		const char *filename)
+{
+	DECLARE_PROC_ADDR(kernel32.dll, USHORT, RtlCaptureStackBackTrace,
+			  ULONG, ULONG, PVOID*, PULONG);
+	struct file_lock_backtrace *result;
+	uintptr_t pcs[62];
+	int count = 0;
+	size_t pcs_size = 0, size;
+
+	if ((fd < 0 || fd >= FILE_LOCK_MAX_FD) && fd != -123)
+		BUG("Called with fd = %d\n", fd);
+
+	if (INIT_PROC_ADDR(RtlCaptureStackBackTrace)) {
+		count = RtlCaptureStackBackTrace(1, ARRAY_SIZE(pcs),
+						 (void **)pcs, NULL);
+		pcs_size = sizeof(uintptr_t) * count;
+	}
+	size = sizeof(*result) + pcs_size + strlen(filename) + 1;
+
+	result = xmalloc(size);
+	result->fd = fd;
+	result->count = count;
+	if (!count)
+		result->pcs = NULL;
+	else {
+		result->pcs = (uintptr_t *)((char *)result + sizeof(*result));
+		memcpy(result->pcs, pcs, pcs_size);
+	}
+
+	result->filename = ((char *)result + sizeof(*result) + pcs_size);
+	strcpy((char *)result->filename, filename);
+
+	if (fd < 0)
+		return result;
+
+	EnterCriticalSection(&backtrace_mutex);
+	if (file_lock_by_fd[fd]) {
+		struct strbuf buf = STRBUF_INIT;
+		strbuf_addf(&buf, "Bogus file_lock (%d). First trace:\n", fd);
+		file_lock_backtrace(file_lock_by_fd[fd], &buf);
+		strbuf_addf(&buf, "\nSecond trace:\n");
+		file_lock_backtrace(result, &buf);
+		BUG(buf.buf);
+	}
+	file_lock_by_fd[fd] = result;
+	hashmap_entry_init(&result->entry, strihash(filename));
+	hashmap_add(&file_lock_map, result);
+	LeaveCriticalSection(&backtrace_mutex);
+
+	return result;
+}
+
+static void current_backtrace(struct strbuf *buf)
+{
+	struct file_lock_backtrace *p = alloc_file_lock_backtrace(-123, "");
+	file_lock_backtrace(p, buf);
+	free(p);
+}
+
+static void remove_file_lock_backtrace(int fd)
+{
+	if (fd < 0 || fd >= FILE_LOCK_MAX_FD)
+		BUG("Called with fd = %d\n", fd);
+
+	EnterCriticalSection(&backtrace_mutex);
+	if (!file_lock_by_fd[fd])
+		BUG("trying to release non-existing lock for fd %d", fd);
+
+	hashmap_remove(&file_lock_map, file_lock_by_fd[fd], NULL);
+	free(file_lock_by_fd[fd]);
+	file_lock_by_fd[fd] = NULL;
+	LeaveCriticalSection(&backtrace_mutex);
+}
+
+static int file_lock_backtrace_cmp(const void *dummy,
+		const struct file_lock_backtrace *a,
+		const struct file_lock_backtrace *b,
+		const void *keydata)
+{
+	return strcasecmp(a->filename,
+			  keydata ? (const char *)keydata : b->filename);
+}
+
+static struct file_lock_backtrace *file_lock_lookup(const char *filename)
+{
+	struct hashmap_entry entry;
+	struct file_lock_backtrace *result;
+
+	hashmap_entry_init(&entry, strihash(filename));
+	EnterCriticalSection(&backtrace_mutex);
+	result = hashmap_get(&file_lock_map, &entry, filename);
+	LeaveCriticalSection(&backtrace_mutex);
+
+	return result;
+}
+
+static void initialize_file_lock_map(void)
+{
+	InitializeCriticalSection(&backtrace_mutex);
+	hashmap_init(&file_lock_map, (hashmap_cmp_fn)file_lock_backtrace_cmp,
+		     NULL, 0);
+}
+#endif
+
 #define HCAST(type, handle) ((type)(intptr_t)handle)
 
 int err_win_to_posix(DWORD winerr)
@@ -405,6 +574,21 @@ int mingw_unlink(const char *pathname)
 		 */
 		if (!_wrmdir(wpathname))
 			return 0;
+#ifdef DEBUG_FILE_LOCKS
+		{
+			struct file_lock_backtrace *p =
+				file_lock_lookup(pathname);
+			if (p) {
+				struct strbuf buf = STRBUF_INIT;
+				strbuf_addf(&buf, "the file '%s' wants "
+					    "to be deleted here:\n", pathname);
+				current_backtrace(&buf);
+				strbuf_addf(&buf, "\nBut it is still open:\n");
+				file_lock_backtrace(p, &buf);
+				die("%s\n", buf.buf);
+			}
+		}
+#endif
 	} while (retry_ask_yes_no(&tries, "Unlink of file '%s' failed. "
 			"Should I try again?", pathname));
 	return -1;
@@ -553,6 +737,10 @@ int mingw_open (const char *filename, int oflags, ...)
 		if (fd >= 0 && set_hidden_flag(wfilename, 1))
 			warning("could not mark '%s' as hidden.", filename);
 	}
+#ifdef DEBUG_FILE_LOCKS
+	if (fd >= 0)
+		alloc_file_lock_backtrace(fd, filename);
+#endif
 	return fd;
 }
 
@@ -601,6 +789,10 @@ FILE *mingw_fopen (const char *filename, const char *otype)
 		errno = ENOENT;
 	if (file && hide && set_hidden_flag(wfilename, 1))
 		warning("could not mark '%s' as hidden.", filename);
+#ifdef DEBUG_FILE_LOCKS
+	if (file)
+		alloc_file_lock_backtrace(fileno(file), filename);
+#endif
 	return file;
 }
 
@@ -609,6 +801,9 @@ FILE *mingw_freopen (const char *filename, const char *otype, FILE *stream)
 	int hide = needs_hiding(filename);
 	FILE *file;
 	wchar_t wfilename[MAX_LONG_PATH], wotype[4];
+#ifdef DEBUG_FILE_LOCKS
+	int oldfd = fileno(stream);
+#endif
 	if (filename && !strcmp(filename, "/dev/null"))
 		filename = "nul";
 	if (xutftowcs_long_path(wfilename, filename) < 0 ||
@@ -621,9 +816,37 @@ FILE *mingw_freopen (const char *filename, const char *otype, FILE *stream)
 	file = _wfreopen(wfilename, wotype, stream);
 	if (file && hide && set_hidden_flag(wfilename, 1))
 		warning("could not mark '%s' as hidden.", filename);
+#ifdef DEBUG_FILE_LOCKS
+	if (file) {
+		remove_file_lock_backtrace(oldfd);
+		alloc_file_lock_backtrace(fileno(file), filename);
+	}
+#endif
 	return file;
 }
 
+#ifdef DEBUG_FILE_LOCKS
+#undef close
+int mingw_close(int fd)
+{
+	int ret = close(fd);
+	if (!ret)
+		remove_file_lock_backtrace(fd);
+	return ret;
+}
+#define close mingw_close
+
+#undef fclose
+int mingw_fclose(FILE *stream)
+{
+	int fd = fileno(stream), ret = fclose(stream);
+	if (!ret)
+		remove_file_lock_backtrace(fd);
+	return ret;
+}
+#define fclose mingw_fclose
+#endif
+
 #undef fflush
 int mingw_fflush(FILE *stream)
 {
@@ -2438,6 +2661,26 @@ int mingw_rename(const char *pold, const char *pnew)
 		    SetFileAttributesW(wpnew, attrs & ~FILE_ATTRIBUTE_READONLY))
 			goto repeat;
 	}
+#ifdef DEBUG_FILE_LOCKS
+	{
+		struct file_lock_backtrace *p = file_lock_lookup(pnew);
+		const char *which = "target";
+		if (!p) {
+			p = file_lock_lookup(pold);
+			which = "source";
+		}
+		if (p) {
+			struct strbuf buf = STRBUF_INIT;
+			strbuf_addf(&buf, "the file '%s' wants to be "
+				    "renamed to '%s' here:\n", pold, pnew);
+			current_backtrace(&buf);
+			strbuf_addf(&buf, "\nBut the %s is still open:\n",
+				    which);
+			file_lock_backtrace(p, &buf);
+			die("%s\n", buf.buf);
+		}
+	}
+#endif
 	if (retry_ask_yes_no(&tries, "Rename from '%s' to '%s' failed. "
 		       "Should I try again?", pold, pnew))
 		goto repeat;
@@ -3313,6 +3556,9 @@ int msc_startup(int argc, wchar_t **w_argv, wchar_t **w_env)
 	fsync_object_files = 1;
 	maybe_redirect_std_handles();
 	adjust_symlink_flags();
+#ifdef DEBUG_FILE_LOCKS
+	initialize_file_lock_map();
+#endif
 
 	/* determine size of argv conversion buffer */
 	maxlen = wcslen(_wpgmptr);
@@ -3381,6 +3627,9 @@ void mingw_startup(void)
 	fsync_object_files = 1;
 	maybe_redirect_std_handles();
 	adjust_symlink_flags();
+#ifdef DEBUG_FILE_LOCKS
+	initialize_file_lock_map();
+#endif
 
 	/* get wide char arguments and environment */
 	si.newmode = 0;
diff --git a/compat/mingw.h b/compat/mingw.h
@@ -245,6 +245,14 @@ int mingw_fflush(FILE *stream);
 ssize_t mingw_write(int fd, const void *buf, size_t len);
 #define write mingw_write
 
+#ifdef DEBUG_FILE_LOCKS
+int mingw_close(int fd);
+#define close mingw_close
+
+int mingw_fclose(FILE *stream);
+#define fclose mingw_fclose
+#endif
+
 int mingw_access(const char *filename, int mode);
 #undef access
 #define access mingw_access
diff --git a/config.mak.uname b/config.mak.uname
@@ -635,6 +635,15 @@ ifneq (,$(findstring MINGW,$(uname_S)))
 	NATIVE_CRLF = YesPlease
 	X = .exe
 	SPARSE_FLAGS = -Wno-one-bit-signed-bitfield
+ifneq (,$(DEBUG_FILE_LOCKS))
+	BACKTRACE_SOURCES := $(patsubst %,compat/libbacktrace/%,atomic.c \
+		alloc.c dwarf.c state.c fileline.c posix.c pecoff.c sort.c \
+		read.c)
+	BACKTRACE_OBJS := $(patsubst %.c,%.o,$(BACKTRACE_SOURCES))
+	COMPAT_OBJS += $(BACKTRACE_OBJS)
+$(BACKTRACE_OBJS): EXTRA_CPPFLAGS = -I compat/libbacktrace
+	COMPAT_CFLAGS += -DDEBUG_FILE_LOCKS
+endif
 ifneq (,$(wildcard ../THIS_IS_MSYSGIT))
 	htmldir = share/doc/git/$(firstword $(subst -, ,$(GIT_VERSION)))/html
 	prefix =
@@ -652,9 +661,11 @@ else
 		# Enable DEP
 		BASIC_LDFLAGS += -Wl,--nxcompat
 		# Enable ASLR (unless debugging)
+		ifeq (,$(DEBUG_FILE_LOCKS))
 		ifneq (,$(findstring -O,$(CFLAGS)))
 			BASIC_LDFLAGS += -Wl,--dynamicbase
 		endif
+		endif
 		ifeq (MINGW32,$(MSYSTEM))
 			prefix = /mingw32
 			BASIC_LDFLAGS += -Wl,--pic-executable,-e,_mainCRTStartup
