allow formatted messages

14 files changed, 129 insertions, 88 deletions

diff --git a/common/nslog_log.hpp b/common/nslog_log.hpp
index d4ea6f6eaa..9f2f3aee7b 100644
--- a/common/nslog_log.hpp
+++ b/common/nslog_log.hpp
@@ -10,6 +10,7 @@ public:
     inline ~NSLogBackend() = default;
 
     void record(EventSeverity severity, Event event, const std::string &msg);
+    void record(EventSeverity severity, Event event, const char* format, ...);
     void record(EventSeverity severity, Event event, int64_t code);
     void record(EventSeverity severity, Event event, int64_t code, const std::string &msg);
 };
diff --git a/common/nslog_log.mm b/common/nslog_log.mm
index eed0810aee..ad685ea8dc 100644
--- a/common/nslog_log.mm
+++ b/common/nslog_log.mm
@@ -11,6 +11,19 @@ void NSLogBackend::record(EventSeverity severity, Event event, const std::string
                                  encoding:NSUTF8StringEncoding]);
 }
 
+
+void NSLogBackend::record(EventSeverity severity, Event event, const char* format, ...) {
+    va_list args;
+    va_start(args, format);
+    const int len = vsnprintf(NULL, 0, format, args);
+    va_end(args);
+    std::unique_ptr<char[]> buffer(new char[len + 1]);
+    va_start(args, format);
+    vsnprintf(buffer.get(), len + 1, format, args);
+    va_end(args);
+    NSLog(@"[%s] %s: %s", stringifyEventSeverity(severity), stringifyEvent(event), buffer.get());
+}
+
 void NSLogBackend::record(EventSeverity severity, Event event, int64_t code) {
     NSLog(@"[%s] %s: (%lld)", stringifyEventSeverity(severity), stringifyEvent(event), code);
 }
diff --git a/common/stderr_log.cpp b/common/stderr_log.cpp
index b3b1fea333..18ad9b3f10 100644
--- a/common/stderr_log.cpp
+++ b/common/stderr_log.cpp
@@ -8,6 +8,15 @@ void StderrLogBackend::record(EventSeverity severity, Event event, const std::st
     std::cerr << "[" << severity << "] " << event << ": " << msg << std::endl;
 }
 
+void StderrLogBackend::record(EventSeverity severity, Event event, const char* format, ...) {
+    std::cerr << "[" << severity << "] " << event << ": ";
+    va_list args;
+    va_start(args, format);
+    vfprintf(stderr, format, args);
+    va_end(args);
+    std::cerr << std::endl;
+}
+
 void StderrLogBackend::record(EventSeverity severity, Event event, int64_t code) {
     std::cerr << "[" << severity << "] " << event << ": (" << code << ")" << std::endl;
 }
diff --git a/common/stderr_log.hpp b/common/stderr_log.hpp
index 32b6850cb7..e2492d3af5 100644
--- a/common/stderr_log.hpp
+++ b/common/stderr_log.hpp
@@ -10,6 +10,7 @@ public:
     inline ~StderrLogBackend() = default;
 
     void record(EventSeverity severity, Event event, const std::string &msg);
+    void record(EventSeverity severity, Event event, const char* format, ...);
     void record(EventSeverity severity, Event event, int64_t code);
     void record(EventSeverity severity, Event event, int64_t code, const std::string &msg);
 };
diff --git a/include/llmr/platform/event.hpp b/include/llmr/platform/event.hpp
index 930f79fac6..c1552b1c6b 100644
--- a/include/llmr/platform/event.hpp
+++ b/include/llmr/platform/event.hpp
@@ -19,7 +19,9 @@ const char *stringifyEventSeverity(EventSeverity eventSeverity);
 ::std::ostream& operator<<(::std::ostream& os, EventSeverity eventSeverity);
 
 enum class Event : uint8_t {
+    General,
     Setup,
+    Shader,
     ParseStyle,
     ParseTile,
     Render,
@@ -30,25 +32,30 @@ Event parseEvent(const char *name);
 const char *stringifyEvent(Event event);
 ::std::ostream& operator<<(::std::ostream& os, Event event);
 
-constexpr EventSeverity enabledEventSeverities[] = {
-#if DEBUG
+struct EventPermutation {
+    const EventSeverity severity;
+    const Event event;
+
+    constexpr bool operator==(const EventPermutation &rhs) const {
+        return severity == rhs.severity && event == rhs.event;
+    }
+};
+
+constexpr EventSeverity disabledEventSeverities[] = {
+#if !DEBUG
     EventSeverity::Debug,
 #endif
-
-#if TESTING
+#if !TESTING
     EventSeverity::Test,
 #endif
+};
+
 
-    EventSeverity::Info,
-    EventSeverity::Warning,
-    EventSeverity::Error,
+constexpr Event disabledEvents[] = {
 };
 
-/* enabled event classes */
-constexpr Event enabledEvents[] = {
-    Event::ParseStyle,
-    Event::ParseTile,
-    Event::HttpRequest,
+constexpr EventPermutation disabledEventPermutations[] = {
+    { EventSeverity::Debug, Event::Shader }
 };
 
 }
diff --git a/include/llmr/platform/log.hpp b/include/llmr/platform/log.hpp
index 48c88a1fdc..7b39370046 100644
--- a/include/llmr/platform/log.hpp
+++ b/include/llmr/platform/log.hpp
@@ -12,6 +12,7 @@ class LogBackend {
 public:
     virtual inline ~LogBackend() = default;
     virtual void record(EventSeverity severity, Event event, const std::string &msg) = 0;
+    virtual void record(EventSeverity severity, Event event, const char* format, ...) = 0;
     virtual void record(EventSeverity severity, Event event, int64_t code) = 0;
     virtual void record(EventSeverity severity, Event event, int64_t code, const std::string &msg) = 0;
 };
@@ -46,8 +47,9 @@ public:
 
     template <typename ...Args>
     static inline void Record(EventSeverity severity, Event event, Args&& ...args) {
-        if (includes(severity, enabledEventSeverities) &&
-            includes(event, enabledEvents)) {
+        if (!includes(severity, disabledEventSeverities) &&
+            !includes(event, disabledEvents) &&
+            !includes({ severity, event }, disabledEventPermutations)) {
             if (Backend) {
                 Backend->record(severity, event, ::std::forward<Args>(args)...);
             }
diff --git a/include/llmr/util/timer.hpp b/include/llmr/util/timer.hpp
index a1e8e05a9d..5dc0cfaf3f 100644
--- a/include/llmr/util/timer.hpp
+++ b/include/llmr/util/timer.hpp
@@ -1,6 +1,8 @@
 #ifndef LLMR_UTIL_TIMER
 #define LLMR_UTIL_TIMER
 
+#include <llmr/platform/event.hpp>
+
 #include <string>
 
 namespace llmr {
@@ -9,24 +11,29 @@ namespace util {
 #ifndef DISABLE_TIMER
 class timer {
 public:
-    timer();
-    timer(const std::string &name);
+    timer(Event event = Event::General);
+    timer(EventSeverity severity, Event event = Event::General);
+    timer(const std::string &name, Event event = Event::General);
+    timer(const std::string &name, EventSeverity severity, Event event = Event::General);
     void report(const std::string &name);
     ~timer();
 
 private:
     const std::string name;
+    EventSeverity severity = EventSeverity::Debug;
+    Event event = Event::General;
     uint64_t start;
 };
 #else
 class timer {
-    inline timer() {}
-    inline timer(const std::string &name) {}
-    inline void report (const std::string &name) {}
+    inline timer(Event event = Event::General);
+    inline timer(EventSeverity severity, Event event = Event::General);
+    inline timer(const std::string &name, Event event = Event::General);
+    inline timer(const std::string &name, EventSeverity severity, Event event = Event::General);
+    inline void report(const std::string &name) {}
     inline ~timer() {}
 };
 #endif
-
 }
 }
 
diff --git a/src/platform/event.cpp b/src/platform/event.cpp
index 8d55074234..c60faaeba6 100644
--- a/src/platform/event.cpp
+++ b/src/platform/event.cpp
@@ -29,7 +29,9 @@ const char *stringifyEventSeverity(EventSeverity eventSeverity) {
 }
 
 Event parseEvent(const char *name) {
+    if (strcmp(name, "General") == 0) return Event::General;
     if (strcmp(name, "Setup") == 0) return Event::Setup;
+    if (strcmp(name, "Shader") == 0) return Event::Shader;
     if (strcmp(name, "ParseStyle") == 0) return Event::ParseStyle;
     if (strcmp(name, "ParseTile") == 0) return Event::ParseTile;
     if (strcmp(name, "Render") == 0) return Event::Render;
@@ -39,7 +41,9 @@ Event parseEvent(const char *name) {
 
 const char *stringifyEvent(Event event) {
      switch (event) {
+        case Event::General: return "General";
         case Event::Setup: return "Setup";
+        case Event::Shader: return "Shader";
         case Event::ParseStyle: return "ParseStyle";
         case Event::ParseTile: return "ParseTile";
         case Event::Render: return "Render";
diff --git a/src/shader/shader.cpp b/src/shader/shader.cpp
index 70b59e7aa3..7775fb6a75 100644
--- a/src/shader/shader.cpp
+++ b/src/shader/shader.cpp
@@ -1,34 +1,24 @@
 #include <llmr/shader/shader.hpp>
 #include <llmr/platform/gl.hpp>
-#if defined(DEBUG)
 #include <llmr/util/timer.hpp>
-#endif
-#include <cstdlib>
-#include <cstdio>
-#include <cstring>
+#include <llmr/platform/log.hpp>
 
 using namespace llmr;
 
 Shader::Shader(const GLchar *vertSource, const GLchar *fragSource)
     : valid(false),
       program(0) {
-#if defined(DEBUG)
-    util::timer timer("shader compilation");
-#endif
+    util::timer timer("shader compilation", Event::Shader);
 
     GLuint vertShader;
     if (!compileShader(&vertShader, GL_VERTEX_SHADER, vertSource)) {
-#if defined(DEBUG)
-        fprintf(stderr, "Vertex shader failed to compile: %s\n", vertSource);
-#endif
+        Log::Error(Event::Shader, "Vertex shader failed to compile: %s", vertSource);
         return;
     }
 
     GLuint fragShader;
     if (!compileShader(&fragShader, GL_FRAGMENT_SHADER, fragSource)) {
-#if defined(DEBUG)
-        fprintf(stderr, "Fragment shader failed to compile: %s\n", fragSource);
-#endif
+        Log::Error(Event::Shader, "Fragment shader failed to compile: %s", fragSource);
         return;
     }
 
@@ -44,20 +34,17 @@ Shader::Shader(const GLchar *vertSource, const GLchar *fragSource)
         GLint status;
         glLinkProgram(program);
 
-#if defined(DEBUG)
-        GLint logLength;
-        glGetProgramiv(program, GL_INFO_LOG_LENGTH, &logLength);
-        if (logLength > 0) {
-            GLchar *log = (GLchar *)malloc(logLength);
-            glGetProgramInfoLog(program, logLength, &logLength, log);
-            fprintf(stderr, "Program link log:\n%s", log);
-            free(log);
-        }
-#endif
-
         glGetProgramiv(program, GL_LINK_STATUS, &status);
         if (status == 0) {
-            fprintf(stderr, "Program failed to link\n");
+            GLint logLength;
+            glGetProgramiv(program, GL_INFO_LOG_LENGTH, &logLength);
+            if (logLength > 0) {
+                GLchar *log = (GLchar *)malloc(logLength);
+                glGetProgramInfoLog(program, logLength, &logLength, log);
+                Log::Error(Event::Shader, "Program failed to link: %s", log);
+                free(log);
+            }
+
             glDeleteShader(vertShader);
             vertShader = 0;
             glDeleteShader(fragShader);
@@ -73,22 +60,17 @@ Shader::Shader(const GLchar *vertSource, const GLchar *fragSource)
         GLint status;
         glValidateProgram(program);
 
-#if defined(DEBUG)
-        GLint logLength;
-        glGetProgramiv(program, GL_INFO_LOG_LENGTH, &logLength);
-        if (logLength > 0) {
-            GLchar *log = (GLchar *)malloc(logLength);
-            glGetProgramInfoLog(program, logLength, &logLength, log);
-            fprintf(stderr, "Program validate log:\n%s", log);
-            free(log);
-        }
-#endif
-
         glGetProgramiv(program, GL_VALIDATE_STATUS, &status);
         if (status == 0) {
-#if defined(DEBUG)
-            fprintf(stderr, "Program failed to validate\n");
-#endif
+            GLint logLength;
+            glGetProgramiv(program, GL_INFO_LOG_LENGTH, &logLength);
+            if (logLength > 0) {
+                GLchar *log = (GLchar *)malloc(logLength);
+                glGetProgramInfoLog(program, logLength, &logLength, log);
+                Log::Error(Event::Shader, "Program failed to validate: %s", log);
+                free(log);
+            }
+
             glDeleteShader(vertShader);
             vertShader = 0;
             glDeleteShader(fragShader);
@@ -119,19 +101,17 @@ bool Shader::compileShader(GLuint *shader, GLenum type, const GLchar *source) {
 
     glCompileShader(*shader);
 
-#if defined(DEBUG)
-    GLint logLength;
-    glGetShaderiv(*shader, GL_INFO_LOG_LENGTH, &logLength);
-    if (logLength > 0) {
-        GLchar *log = (GLchar *)malloc(logLength);
-        glGetShaderInfoLog(*shader, logLength, &logLength, log);
-        fprintf(stderr, "Shader compile log:\n%s", log);
-        free(log);
-    }
-#endif
-
     glGetShaderiv(*shader, GL_COMPILE_STATUS, &status);
     if (status == 0) {
+        GLint logLength;
+        glGetShaderiv(*shader, GL_INFO_LOG_LENGTH, &logLength);
+        if (logLength > 0) {
+            GLchar *log = (GLchar *)malloc(logLength);
+            glGetShaderInfoLog(*shader, logLength, &logLength, log);
+            Log::Error(Event::Shader, "Shader failed to compile: %s", log);
+            free(log);
+        }
+
         glDeleteShader(*shader);
         *shader = 0;
         return false;
diff --git a/src/util/timer.cpp b/src/util/timer.cpp
index 6d4fc1135b..efa2b974dc 100644
--- a/src/util/timer.cpp
+++ b/src/util/timer.cpp
@@ -1,28 +1,29 @@
 #ifndef DISABLE_TIMER
 #include <llmr/util/timer.hpp>
 #include <llmr/util/time.hpp>
+#include <llmr/platform/log.hpp>
 
 #include <iostream>
 #include <atomic>
 
 using namespace llmr::util;
 
-std::atomic<int> indent;
+timer::timer(Event event)
+    : event(event), start(now()) {}
 
-timer::timer() : start(now()) {
-    indent++;
-}
+timer::timer(EventSeverity severity, Event event)
+    : severity(severity), event(event), start(now()) {}
 
-timer::timer(const std::string &name) : name(name), start(now()) {
-    indent++;
-}
+timer::timer(const std::string &name, Event event)
+    : name(name), event(event), start(now()) {}
+
+timer::timer(const std::string &name, EventSeverity severity, Event event)
+    : name(name), severity(severity), event(event), start(now()) {}
 
 void timer::report(const std::string &name) {
     timestamp duration = now() - start;
-    std::cerr << std::string((indent - 1) * 4, ' ')
-              << name << ": "
-              << (double)(duration) / 1_millisecond
-              << "ms" << std::endl;
+
+    Log::Record(severity, event, name + ": " + std::to_string((double)(duration) / 1_millisecond) + "ms");
     start += duration;
 }
 
@@ -30,6 +31,5 @@ timer::~timer() {
     if (name.size()) {
         report(name);
     }
-    indent--;
 }
 #endif
diff --git a/test/fixtures/fixture_log.cpp b/test/fixtures/fixture_log.cpp
index d260927b5e..159f927e29 100644
--- a/test/fixtures/fixture_log.cpp
+++ b/test/fixtures/fixture_log.cpp
@@ -4,6 +4,10 @@
 
 namespace llmr {
 
+FixtureLogBackend::~FixtureLogBackend() {
+    std::cerr << unchecked();
+}
+
 size_t FixtureLogBackend::count(const LogMessage &message) const {
     size_t count = 0;
     for (const LogMessage &msg : messages) {
diff --git a/test/fixtures/fixture_log.hpp b/test/fixtures/fixture_log.hpp
index befba8b2c7..5561004a50 100644
--- a/test/fixtures/fixture_log.hpp
+++ b/test/fixtures/fixture_log.hpp
@@ -36,12 +36,24 @@ public:
         mutable bool checked = false;
     };
 
-    inline ~FixtureLogBackend() = default;
+    ~FixtureLogBackend();
 
     void record(EventSeverity severity, Event event, const std::string &msg) {
         messages.emplace_back(severity, event, msg);
     }
 
+    void record(EventSeverity severity, Event event, const char* format, ...) {
+        va_list args;
+        va_start(args, format);
+        const int len = vsnprintf(NULL, 0, format, args);
+        va_end(args);
+        std::unique_ptr<char[]> buffer(new char[len + 1]);
+        va_start(args, format);
+        vsnprintf(buffer.get(), len + 1, format, args);
+        va_end(args);
+        messages.emplace_back(severity, event, std::string { buffer.get(), len });
+    }
+
     void record(EventSeverity severity, Event event, int64_t code) {
         messages.emplace_back(severity, event, code);
     }
diff --git a/test/fixtures/fixture_request.cpp b/test/fixtures/fixture_request.cpp
index c2e209bc61..b106dfe306 100644
--- a/test/fixtures/fixture_request.cpp
+++ b/test/fixtures/fixture_request.cpp
@@ -54,7 +54,7 @@ platform::request_http(const std::string &url,
     if (err < 0) {
         req->res->code = err;
         req->res->error_message = uv_strerror(err);
-        fprintf(stderr, "[WARNING] fixture request: %s\n", uv_strerror(err));
+        Log::Warning(Event::HttpRequest, err, url + ": " + uv_strerror(err));
         req->complete();
         return req;
     }
@@ -72,7 +72,7 @@ platform::request_http(const std::string &url,
     if (err < 0) {
         req->res->code = err;
         req->res->error_message = uv_strerror(err);
-        fprintf(stderr, "[WARNING] fixture request: %s\n", uv_strerror(err));
+        Log::Warning(Event::HttpRequest, err, url + ": " + uv_strerror(err));
         req->complete();
         return req;
     }
@@ -84,14 +84,13 @@ platform::request_http(const std::string &url,
     if (err < 0) {
         req->res->code = err;
         req->res->error_message = uv_strerror(err);
-        fprintf(stderr, "[WARNING] fixture request: %s\n", uv_strerror(err));
+        Log::Warning(Event::HttpRequest, err, url + ": " + uv_strerror(err));
         req->complete();
         return req;
     }
 
     req->res->body.swap(body);
     req->res->code = 200;
-    // fprintf(stderr, "[INFO] fixture request completed: %s\n", clean_url.c_str());
     Log::Info(Event::HttpRequest, 200, url);
     req->complete();
 
diff --git a/test/headless.cpp b/test/headless.cpp
index fac38f9fdc..523f66d0d2 100644
--- a/test/headless.cpp
+++ b/test/headless.cpp
@@ -35,6 +35,8 @@ TEST_P(HeadlessTest, render) {
     ASSERT_EQ(false, doc.HasParseError());
     ASSERT_EQ(true, doc.IsObject());
 
+    Log::Set<FixtureLogBackend>();
+
     // Setup OpenGL
     HeadlessView view;
     Map map(view);