feat/test: add log_trace, use get_log_level, improve log tests

extism-pdk.hpp

@@ -27,6 +27,14 @@ namespace extism {
 #define EXTISM_IMPORT_USER(b)                                                  \
   __attribute__((import_module(EXTISM_USER_MODULE), import_name(b)))
 
+typedef enum {
+  Trace,
+  Debug,
+  Info,
+  Warn,
+  Error,
+} Log;
+
 namespace imports {
 typedef uint64_t ExtismPointer;
 class RawHandle {
@@ -71,14 +79,19 @@ extern int32_t http_status_code(void);
 EXTISM_IMPORT_ENV("http_headers")
 extern RawHandle http_headers(void);
 
-EXTISM_IMPORT_ENV("log_info")
-extern void log_info(const RawHandle);
+EXTISM_IMPORT_ENV("log_trace")
+extern void log_trace(const RawHandle);
 EXTISM_IMPORT_ENV("log_debug")
 extern void log_debug(const RawHandle);
+EXTISM_IMPORT_ENV("log_info")
+extern void log_info(const RawHandle);
 EXTISM_IMPORT_ENV("log_warn")
 extern void log_warn(const RawHandle);
 EXTISM_IMPORT_ENV("log_error")
 extern void log_error(const RawHandle);
+static_assert(sizeof(Log) == sizeof(int32_t));
+EXTISM_IMPORT_ENV("get_log_level")
+extern Log get_log_level();
 
 EXTISM_IMPORT_ENV("output_set")
 extern void output_set(const ExtismPointer, const uint64_t);
@@ -161,18 +174,12 @@ bool var_set(const std::string_view name, const std::string_view value);
 template <typename T>
 bool var_set_type(const std::string_view name, const T &data);
 
-bool log_info(const std::string_view message);
+bool log_trace(const std::string_view message);
 bool log_debug(const std::string_view message);
+bool log_info(const std::string_view message);
 bool log_warn(const std::string_view message);
 bool log_error(const std::string_view message);
 
-typedef enum {
-  Info,
-  Debug,
-  Warn,
-  Error,
-} Log;
-
 bool log(const std::string_view message, const Log level);
 
 template <typename T> void output(UniqueHandle<T> handle);
@@ -460,17 +467,23 @@ bool var_set(const std::string_view name, const std::string_view value) {
 
 // Write to Extism log
 bool log(const std::string_view message, const Log level) {
+  if (level < imports::get_log_level()) {
+    return false;
+  }
   auto buf = Handle<const char>::from(message);
   if (!buf) {
     return false;
   }
   switch (level) {
-  case Info:
-    imports::log_info(*buf);
+  case Trace:
+    imports::log_trace(*buf);
     break;
   case Debug:
     imports::log_debug(*buf);
     break;
+  case Info:
+    imports::log_info(*buf);
+    break;
   case Warn:
     imports::log_warn(*buf);
     break;
@@ -481,9 +494,9 @@ bool log(const std::string_view message, const Log level) {
   return true;
 }
 
-bool log_info(const std::string_view message) { return log(message, Info); }
+bool log_trace(const std::string_view message) { return log(message, Trace); }
 bool log_debug(const std::string_view message) { return log(message, Debug); }
-
+bool log_info(const std::string_view message) { return log(message, Info); }
 bool log_warn(const std::string_view message) { return log(message, Warn); }
 bool log_error(const std::string_view message) { return log(message, Error); }
 

tests/Makefile

@@ -24,10 +24,11 @@ test-strvar: strvar.wasm
 	extism call strvar.wasm --wasi --loop 5 run_test | grep -Fxq 'aaaaa'
 
 test-log: log.wasm
-	extism call log.wasm --wasi --input 'debug' --log-level=debug run_test 2>&1 | grep -q 'debug'
-	extism call log.wasm --wasi --input 'info' --log-level=debug run_test 2>&1 | grep -q 'info'
-	extism call log.wasm --wasi --input 'warn' --log-level=debug run_test 2>&1 | grep -q 'warn'
-	extism call log.wasm --wasi --input 'error' --log-level=debug run_test 2>&1 | grep -q 'error'
+	extism call log.wasm --wasi --log-level=trace run_test 2>&1 | perl log-matches.pl trace
+	extism call log.wasm --wasi --log-level=debug run_test 2>&1 | perl log-matches.pl debug
+	extism call log.wasm --wasi --log-level=info run_test 2>&1 | perl log-matches.pl info
+	extism call log.wasm --wasi --log-level=warn run_test 2>&1 | perl log-matches.pl warn
+	extism call log.wasm --wasi --log-level=error run_test 2>&1 | perl log-matches.pl error
 
 test-http: http.wasm
 	extism call http.wasm --wasi --input "" --allow-host "*" --enable-http-response-headers --log-level=debug run_test

tests/log-matches.pl

@@ -0,0 +1,20 @@
+#!/usr/bin/env perl
+use strict; use warnings;
+
+my @levels = qw(trace debug info warn error);
+my %levelmap = map { $levels[$_] => $_ } 0..$#levels;
+@ARGV or die "level must be provided";
+my $level = $levelmap{$ARGV[0]};
+my @unexpected = @levels[0..$level-1];
+my $i = $level;
+while(my $line = <STDIN>) {
+    my @found = grep {$line =~ /$_/ } @unexpected;
+    if (@found) {
+        die "Invalid level(s) found '" . join(', ', @found) . "'";
+    }
+    $i < @levels or next;
+    if ($line =~ /$levels[$i]/) {
+        $i++;
+    }
+}
+$i == @levels or die "Did not find level: $levels[$i]";

tests/log.cpp

@@ -5,18 +5,11 @@
 int32_t EXTISM_EXPORTED_FUNCTION(run_test) {
   // test logging
   {
-    const std::string input = extism::input().string();
-    if (input == "debug") {
-      extism::log_debug("debug");
-    } else if (input == "info") {
-      extism::log_info("info");
-    } else if (input == "warn") {
-      extism::log_info("warn");
-    } else if (input == "error") {
-      extism::log_error("error");
-    } else {
-      assert(0);
-    }
+    extism::log_trace("trace");
+    extism::log_debug("debug");
+    extism::log_info("info");
+    extism::log_warn("warn");
+    extism::log_error("error");
   }
 
   return 0;