Merge pull request #566 from mkilgore/logging-changes-2

Add built-in logging support and other fixes

Makefile

@@ -25,6 +25,7 @@ EXE_LIBS :=
 
 ifeq ($(OS),lnx)
 	lnx := y
+	unix := y
 
 	PATH_INTERNAL := ./internal
 	PATH_INTERNAL_SRC := $(PATH_INTERNAL)/source
@@ -84,6 +85,7 @@ endif
 
 ifeq ($(OS),osx)
 	osx := y
+	unix := y
 
 	PATH_INTERNAL := ./internal
 	PATH_INTERNAL_SRC := $(PATH_INTERNAL)/source
@@ -163,6 +165,14 @@ ifeq ($(OS),osx)
 	endif
 endif
 
+# Linux and Mac OS need this to ensure symbols are kept in the symbol table in
+# the executable, which allows dladdr() to work for stacktrace resolution.
+ifeq ($(unix),y)
+ifeq ($(STRIP_SYMBOLS),n)
+	CXXLIBS += -rdynamic
+endif
+endif
+
 QB_QBX_SRC := $(PATH_INTERNAL_C)/qbx$(TEMP_ID).cpp
 QB_QBX_OBJ := $(patsubst %.cpp,%.o,$(QB_QBX_SRC))
 

internal/c/libqb.cpp

@@ -12,6 +12,7 @@
 #    include <mach-o/dyld.h> //required for _NSGetExecutablePath
 #endif
 
+
 #include "audio.h"
 #include "bitops.h"
 #include "cmem.h"
@@ -34,6 +35,7 @@
 #include "image.h"
 #include "keyhandler.h"
 #include "mac-mouse-support.h"
+#include "logging.h"
 #include "mem.h"
 #include "mutex.h"
 #include "qblist.h"
@@ -45,6 +47,7 @@
 // These are here because they are used in func__loadfont()
 #include <algorithm>
 #include <string>
+#include <vector>
 
 int32 disableEvents = 0;
 
@@ -29387,9 +29390,59 @@ int32 func__scaledheight() {
 
 extern void set_dynamic_info();
 
+#ifdef QB64_WINDOWS
+static bool isValidCygwinPipe(int fd) {
+    HANDLE h = (HANDLE) _get_osfhandle(fd);
+    if (h == INVALID_HANDLE_VALUE) {
+        return false;
+    }
+
+    if (GetFileType(h) != FILE_TYPE_PIPE) {
+        return false;
+    }
+
+    size_t size = 4096;
+    std::vector<char> nameinfoBuf(sizeof(FILE_NAME_INFO) + sizeof(WCHAR) * size);
+    FILE_NAME_INFO *nameinfo = reinterpret_cast<FILE_NAME_INFO *>(nameinfoBuf.data());
+
+    if (GetFileInformationByHandleEx(h, FileNameInfo, nameinfo, size)) {
+        nameinfo->FileName[nameinfo->FileNameLength / sizeof(WCHAR)] = L'\0';
+
+        // When a valid pipe is found, disable buffering so that results are seen immediately
+        if (wcsncmp(nameinfo->FileName, L"\\msys-", 6) == 0) {
+            setbuf(stdout, NULL);
+            setbuf(stderr, NULL);
+            return true;
+        } else if (wcsncmp(nameinfo->FileName, L"\\cygwin-", 8) == 0) {
+            setbuf(stdout, NULL);
+            setbuf(stderr, NULL);
+            return true;
+        }
+    }
+
+    return false;
+}
+#endif
+
 int main(int argc, char *argv[]) {
     clock_init();
 
+#ifdef QB64_WINDOWS
+    // `isValidCygwinPipe()` checks for Cygwin-based stdout, which is good
+    // enough to use directly. Otherwise we try to connect to the console we
+    // were started from (if there is one).
+    //
+    // If we're a console program and `AttachConsole()` did not work then we
+    // will end up spawning our own console.
+    if (!isValidCygwinPipe(STDOUT_FILENO) && AttachConsole(ATTACH_PARENT_PROCESS)) {
+        freopen("CONOUT$", "w", stdout);
+        freopen("CONOUT$", "w", stderr);
+    }
+#endif
+
+    libqb_log_init();
+    libqb_log_info("Program starting.");
+
 #if defined(QB64_LINUX) && defined(X11)
     XInitThreads();
 #endif

internal/c/libqb/build.mk

@@ -22,6 +22,20 @@ libqb-objs-y += $(PATH_LIBQB)/src/qbs_cmem.o
 libqb-objs-y += $(PATH_LIBQB)/src/qbs_mk_cv.o
 libqb-objs-y += $(PATH_LIBQB)/src/string_functions.o
 
+libqb-objs-y += $(PATH_LIBQB)/src/logging/logging.o
+libqb-objs-y += $(PATH_LIBQB)/src/logging/qb64pe_symbol.o
+libqb-objs-y += $(PATH_LIBQB)/src/logging/stacktrace.o
+libqb-objs-y += $(PATH_LIBQB)/src/logging/handlers/fp_handler.o
+
+# Windows MinGW symbol resolution
+libqb-objs-$(win) += $(PATH_LIBQB)/src/logging/mingw/file.o
+libqb-objs-$(win) += $(PATH_LIBQB)/src/logging/mingw/pe.o
+libqb-objs-$(win) += $(PATH_LIBQB)/src/logging/mingw/pe_symtab.o
+libqb-objs-$(win) += $(PATH_LIBQB)/src/logging/mingw/symbol.o
+
+# Unix symbol resolution
+libqb-objs-$(unix) += $(PATH_LIBQB)/src/logging/unix/symbol.o
+
 libqb-objs-$(DEP_HTTP) += $(PATH_LIBQB)/src/http.o
 libqb-objs-y$(DEP_HTTP) += $(PATH_LIBQB)/src/http-stub.o
 

internal/c/libqb/include/datetime.h

@@ -4,7 +4,7 @@
 #include "qbs.h"
 #include <stdint.h>
 
-#ifdef QB64_LINUX
+#if defined(QB64_LINUX) || defined(QB64_WINDOWS)
 // Initializes the clock returned by 'GetTicks()' so that it starts from zero
 // Should be called at the very beginning of the program
 void clock_init();

internal/c/libqb/include/image.h

@@ -23,16 +23,25 @@
 #include <stdio.h>
 #include <stdlib.h>
 
-#if defined(IMAGE_DEBUG) && IMAGE_DEBUG > 0
-#    define IMAGE_DEBUG_PRINT(_fmt_, _args_...)                                                                                                                \
-        fprintf(stderr, "\e[1;37mDEBUG: %s:%d:%s(): \e[1;33m" _fmt_ "\e[1;37m\n", __FILE__, __LINE__, __func__, ##_args_)
-#    define IMAGE_DEBUG_CHECK(_exp_)                                                                                                                           \
-        if (!(_exp_))                                                                                                                                          \
-        IMAGE_DEBUG_PRINT("\e[0;31mCondition (%s) failed", #_exp_)
-#else
-#    define IMAGE_DEBUG_PRINT(_fmt_, _args_...) // Don't do anything in release builds
-#    define IMAGE_DEBUG_CHECK(_exp_)            // Don't do anything in release builds
-#endif
+#include "logging.h"
+
+#define image_log_trace(...) \
+    libqb_log_with_scope_trace(logscope::Image, __VA_ARGS__)
+
+#define image_log_info(...) \
+    libqb_log_with_scope_info(logscope::Image, __VA_ARGS__)
+
+#define image_log_warn(...) \
+    libqb_log_with_scope_warn(logscope::Image, __VA_ARGS__)
+
+#define image_log_error(...) \
+    libqb_log_with_scope_error(logscope::Image, __VA_ARGS__)
+
+#define IMAGE_DEBUG_CHECK(_exp_) \
+    do { \
+        if (!(_exp_)) \
+            image_log_warn("Condition (%s) failed", #_exp_); \
+    } while (0)
 
 // This is returned to the caller if something goes wrong while loading the image
 #define INVALID_IMAGE_HANDLE -1

internal/c/libqb/include/logging.h

@@ -0,0 +1,69 @@
+#pragma once
+
+#include <stdint.h>
+
+#include "qbs.h"
+
+enum class loglevel {
+    Trace,
+    Information,
+    Warning,
+    Error,
+};
+
+enum class logscope {
+    Runtime,
+    QB64,
+    Libqb,
+    Audio,
+    Image,
+
+    Count,
+};
+
+void libqb_log_init();
+void libqb_log(loglevel lvl, logscope scope, const char *file, const char *func, int line, const char *fmt, ...);
+void libqb_log_qb64(loglevel lvl, logscope scope, const char *file, const char *func, int line, const char *fmt, ...);
+void libqb_log_qbs(loglevel lvl, logscope scope, const char *file, const char *func, int line, qbs *str);
+
+// Returns 1 to 4, indicating a min level of Trace to Error
+uint32_t func__logminlevel();
+
+
+#define libqb_log_with_scope_trace(scope, fmt, ...) \
+    libqb_log(loglevel::Trace, (scope), __FILE__, __func__, __LINE__, fmt, ## __VA_ARGS__)
+
+#define libqb_log_with_scope_info(scope, fmt, ...) \
+    libqb_log(loglevel::Information, (scope), __FILE__, __func__, __LINE__, fmt, ## __VA_ARGS__)
+
+#define libqb_log_with_scope_warn(scope, fmt, ...) \
+    libqb_log(loglevel::Warning, (scope), __FILE__, __func__, __LINE__, fmt, ## __VA_ARGS__)
+
+#define libqb_log_with_scope_error(scope, fmt, ...) \
+    libqb_log(loglevel::Error, (scope), __FILE__, __func__, __LINE__, fmt, ## __VA_ARGS__)
+
+
+#define libqb_log_trace(...) \
+    libqb_log_with_scope_trace(logscope::Libqb, __VA_ARGS__)
+
+#define libqb_log_info(...) \
+    libqb_log_with_scope_info(logscope::Libqb, __VA_ARGS__)
+
+#define libqb_log_warn(...) \
+    libqb_log_with_scope_warn(logscope::Libqb, __VA_ARGS__)
+
+#define libqb_log_error(...) \
+    libqb_log_with_scope_error(logscope::Libqb, __VA_ARGS__)
+
+
+#define sub__logtrace(file, func, line, qbs) \
+    libqb_log_qbs(loglevel::Trace, logscope::QB64, file, func, line, (qbs))
+
+#define sub__loginfo(file, func, line, qbs) \
+    libqb_log_qbs(loglevel::Information, logscope::QB64, file, func, line, (qbs))
+
+#define sub__logwarn(file, func, line, qbs) \
+    libqb_log_qbs(loglevel::Warning, logscope::QB64, file, func, line, (qbs))
+
+#define sub__logerror(file, func, line, qbs) \
+    libqb_log_qbs(loglevel::Error, logscope::QB64, file, func, line, (qbs))

internal/c/libqb/src/datetime.cpp

@@ -6,6 +6,7 @@
 
 #ifdef QB64_WINDOWS
 #    include <synchapi.h>
+#    include <profileapi.h>
 #endif
 
 #include "datetime.h"
@@ -37,7 +38,7 @@ static int64_t orwl_gettime(void) {
 }
 #endif
 
-#ifdef QB64_LINUX
+#if defined(QB64_LINUX)
 static int64_t initial_tick = 0;
 
 void clock_init() {
@@ -51,13 +52,31 @@ int64_t GetTicks() {
     clock_gettime(CLOCK_MONOTONIC, &tp);
     return (tp.tv_sec * 1000 + tp.tv_nsec / 1000000) - initial_tick;
 }
-#elif defined QB64_MACOSX
+#elif defined QB64_WINDOWS
+static int64_t initial_tick = 0;
+static LARGE_INTEGER tick_freq;
+
+void clock_init() {
+    QueryPerformanceFrequency(&tick_freq);
+
+    // When GetTicks() is called here initial_tick is zero, so as a result
+    // GetTicks() returns the original value of the clock.
+    initial_tick = GetTicks();
+}
+
 int64_t GetTicks() {
-    return orwl_gettime();
+    LARGE_INTEGER count;
+
+    QueryPerformanceCounter(&count);
+
+    uint64_t sec = count.QuadPart / tick_freq.QuadPart;
+    uint64_t milli = ((count.QuadPart % tick_freq.QuadPart) * 1000 + tick_freq.QuadPart / 2) / tick_freq.QuadPart;
+
+    return sec * 1000 + milli - initial_tick;
 }
-#else
+#elif defined QB64_MACOSX
 int64_t GetTicks() {
-    return ((((int64_t)clock()) * ((int64_t)1000)) / ((int64_t)CLOCKS_PER_SEC));
+    return orwl_gettime();
 }
 #endif
 

internal/c/libqb/src/error_handle.cpp

@@ -8,6 +8,7 @@
 
 #include "command.h"
 #include "error_handle.h"
+#include "logging.h"
 #include "event.h"
 #include "gui.h"
 
@@ -219,6 +220,7 @@ void fix_error() {
 }
 
 void error(int32_t error_number) {
+    libqb_log_error("QB64 Error %d reported: %s", error_number, human_error(error_number));
 
     // critical errors:
 

internal/c/libqb/src/glut-main-thread.cpp

@@ -18,6 +18,7 @@
 #    include <GL/freeglut.h>
 #endif
 
+#include "logging.h"
 #include "completion.h"
 #include "glut-thread.h"
 #include "gui.h"
@@ -176,6 +177,7 @@ void libqb_start_main_thread(int argc, char **argv) {
 //
 // This is accomplished by simply queuing a GLUT message that calls exit() for us.
 void libqb_exit(int exitcode) {
+    libqb_log_info("Program exiting with code: %d\n", exitcode);
     // If GLUT isn't running then we're free to do the exit() call from here
     if (!libqb_is_glut_up())
         exit(exitcode);

internal/c/libqb/src/logging/handlers/fp_handler.cpp

@@ -0,0 +1,53 @@
+
+#include "libqb-common.h"
+
+#include <string.h>
+#include <stdlib.h>
+#include <string>
+#include <cstring>
+#include <stdio.h>
+
+#include "logging.h"
+#include "../logging_private.h"
+
+void fp_log_writer::write(struct log_entry *entry) {
+    if (!fp)
+        return;
+
+    const char *scope = logScopeName(entry->scope);
+
+    // The main code may not have a file associated with it when compiled from
+    // the IDE
+    if (entry->file && *entry->file)
+        fprintf(fp, "[%0.5lf] %s %s %s: %s: %d: %s\n",
+                entry->timestamp,
+                logLevelName(entry->level),
+                scope? scope: "",
+                entry->file,
+                entry->func.c_str(),
+                entry->line,
+                entry->message.c_str());
+    else
+        fprintf(fp, "[%0.5lf] %s %s %s: %d: %s\n",
+                entry->timestamp,
+                logLevelName(entry->level),
+                scope? scope: "",
+                entry->func.c_str(),
+                entry->line,
+                entry->message.c_str());
+
+    if (entry->stacktrace != "")
+        fprintf(fp, "%s", entry->stacktrace.c_str());
+}
+
+console_log_handler::console_log_handler() {
+    fp = stderr;
+}
+
+file_log_handler::file_log_handler() {
+    const char *filepath = getenv("QB64PE_LOG_FILE_PATH");
+
+    fp = fopen(filepath, "a");
+    if (!fp)
+        fprintf(stderr, "Unable to open file '%s' for logging!", filepath);
+}