Repository: simdjson/simdjson (cpp)

Issue:
Enable error logging
Related issue #506 

### Feature Request

To enable logging of errors only. Currently, setting `SIMDJSON_VERBOSE_LOGGING` will log errors and other info. It would be nice to differentiate the logs into different levels and configure the log levels to be logged via an environment variable / compile option.

Is this a feature that would be desired? Should we implement this with an environment variable or compile option?

### Other notes

The motivation behind this is because I'd like to know the key passed in when we receive `NO_SUCH_FIELD` error code is returned. Enabling verbose logging would be too expensive, because I only need the logs when an error occurs.

### Possible Implementation

I am willing to help and make the changes.

My proposal is to use a environment variable `SIMDJSON_LOG_LEVEL`, which defaults to `INFO`. To log error messages only, we compile with `SIMDJSON_VERBOSE_LOGGING` and set the env variable `SIMDJSON_LOG_LEVEL` to `ERROR`.

1. Add enum class `log_level` in the logger with 2 levels, `INFO`, `ERROR`
2. Add method `should_log(log_level)` in the logger class. It will fetch the env variable on first invocation.
3. Modify `log_line` to take in `log_level` as an additional param (should I default this to `INFO`?)
4. inside `log_line` do something like
```c++
if (LOG_ENABLED && simdjson_unlikely(should_log(log_level)))
{
  // logging impl ...
}
```

Pull request description:
Introduce logging levels for conditional logging and log key for NO_SUCH_FIELD error
This resolves #2003

### `SIMDJSON_LOG_LEVEL` Environment variable

Introduces an environment variable `SIMDJSON_LOG_LEVEL` which is available when compiled with the compile option `SIMDJSON_VERBOSE_LOGGING`

`SIMDJSON_LOG_LEVEL` can either be `INFO` or `ERROR`

### Key not found logging

Added logging for key when `NO_SUCH_FIELD` error occurs.

Patch:
diff --git a/README.md b/README.md
index e0f1fedf..336d6265 100644
--- a/README.md
+++ b/README.md
@@ -28,16 +28,37 @@ This library is part of the [Awesome Modern C++](https://awesomecpp.com) list.
 Table of Contents
 -----------------
 
+* [Real-world usage](#real-world-usage)
 * [Quick Start](#quick-start)
 * [Documentation](#documentation)
 * [Performance results](#performance-results)
-* [Real-world usage](#real-world-usage)
 * [Bindings and Ports of simdjson](#bindings-and-ports-of-simdjson)
 * [About simdjson](#about-simdjson)
 * [Funding](#funding)
 * [Contributing to simdjson](#contributing-to-simdjson)
 * [License](#license)
 
+
+Real-world usage
+----------------
+
+- [ClickHouse](https://github.com/ClickHouse/ClickHouse)
+- [Facebook/Meta Velox](https://velox-lib.io)
+- [milvus](https://github.com/milvus-io/milvus)
+- [Clang Build Analyzer](https://github.com/aras-p/ClangBuildAnalyzer)
+- [Shopify HeapProfiler](https://github.com/Shopify/heap-profiler)
+- [StarRocks](https://github.com/StarRocks/starrocks)
+- [Microsoft FishStore](https://github.com/microsoft/FishStore)
+- [Intel PCM](https://github.com/intel/pcm)
+- [WatermelonDB](https://github.com/Nozbe/WatermelonDB)
+- [Apache Doris](https://github.com/apache/doris)
+- [Dgraph](https://github.com/dgraph-io/dgraph)
+- [UJRPC](https://github.com/unum-cloud/ujrpc)
+- [fastgltf](https://github.com/spnda/fastgltf)
+- [vast](https://github.com/tenzir/vast)
+
+If you are planning to use simdjson in a product, please work from one of our releases.
+
 Quick Start
 -----------
 
@@ -110,24 +131,6 @@ For NDJSON files, we can exceed 3 GB/s with [our  multithreaded parsing function
 
 
 
-Real-world usage
-----------------
-
-- [ClickHouse](https://github.com/ClickHouse/ClickHouse)
-- [Clang Build Analyzer](https://github.com/aras-p/ClangBuildAnalyzer)
-- [Shopify HeapProfiler](https://github.com/Shopify/heap-profiler)
-- [StarRocks](https://github.com/StarRocks/starrocks)
-- [Microsoft FishStore](https://github.com/microsoft/FishStore)
-- [Intel PCM](https://github.com/intel/pcm)
-- [WatermelonDB](https://github.com/Nozbe/WatermelonDB)
-- [Apache Doris](https://github.com/apache/doris)
-- [Dgraph](https://github.com/dgraph-io/dgraph)
-- [UJRPC](https://github.com/unum-cloud/ujrpc)
-- [fastgltf](https://github.com/spnda/fastgltf)
-- [Clang Build Analyzer](https://github.com/aras-p/ClangBuildAnalyzer)
-- [vast](https://github.com/tenzir/vast)
-
-If you are planning to use simdjson in a product, please work from one of our releases.
 
 Bindings and Ports of simdjson
 ------------------------------
diff --git a/doc/basics.md b/doc/basics.md
index 8431885f..71b62d0a 100644
--- a/doc/basics.md
+++ b/doc/basics.md
@@ -1894,4 +1894,4 @@ Performance Tips
 	std::string_view year = data["year"];
 	std::string_view rating = data["rating"];
   ```
-- To better understand the operation of your On Demand parser, and whether it is performing as well as you think it should be, there is a  logger feature built in to simdjson! To use it, define the pre-processor directive `SIMDJSON_VERBOSE_LOGGING` prior to including the `simdjson.h` header, which enables logging in simdjson. Run your code. It may generate a lot of logging output; adding printouts from your application that show each section may be helpful. The log’s output will show step-by-step information on state, buffer pointer position, depth, and key retrieval status.
+- To better understand the operation of your On Demand parser, and whether it is performing as well as you think it should be, there is a  logger feature built in to simdjson! To use it, define the pre-processor directive `SIMDJSON_VERBOSE_LOGGING` prior to including the `simdjson.h` header, which enables logging in simdjson. Run your code. It may generate a lot of logging output; adding printouts from your application that show each section may be helpful. The log’s output will show step-by-step information on state, buffer pointer position, depth, and key retrieval status. The log level is set to `INFO` by default, but can be modified with the environment variable `SIMDJSON_LOG_LEVEL`. Setting the environment variable `SIMDJSON_LOG_LEVEL` to `ERROR` will log only errors.
diff --git a/include/simdjson/generic/ondemand/json_iterator.h b/include/simdjson/generic/ondemand/json_iterator.h
index 94ba59bd..e5bfc805 100644
--- a/include/simdjson/generic/ondemand/json_iterator.h
+++ b/include/simdjson/generic/ondemand/json_iterator.h
@@ -297,8 +297,8 @@ protected:
   friend class raw_json_string;
   friend class parser;
   friend class value_iterator;
-  friend simdjson_inline void logger::log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta) noexcept;
-  friend simdjson_inline void logger::log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail) noexcept;
+  friend simdjson_inline void logger::log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta, logger::log_level level) noexcept;
+  friend simdjson_inline void logger::log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail, logger::log_level level) noexcept;
 }; // json_iterator
 
 } // namespace ondemand
diff --git a/include/simdjson/generic/ondemand/logger-inl.h b/include/simdjson/generic/ondemand/logger-inl.h
index fc490af0..89adf516 100644
--- a/include/simdjson/generic/ondemand/logger-inl.h
+++ b/include/simdjson/generic/ondemand/logger-inl.h
@@ -1,3 +1,4 @@
+#include <memory>
 namespace simdjson {
 namespace SIMDJSON_IMPLEMENTATION {
 namespace ondemand {
@@ -18,36 +19,68 @@ static inline char printable_char(char c) {
   }
 }
 
+static inline log_level get_log_level_from_env()
+{
+  SIMDJSON_PUSH_DISABLE_WARNINGS
+  SIMDJSON_DISABLE_DEPRECATED_WARNING // Disable CRT_SECURE warning on MSVC: manually verified this is safe
+  char *lvl = getenv("SIMDJSON_LOG_LEVEL");
+  SIMDJSON_POP_DISABLE_WARNINGS
+  if (lvl && simdjson_strcasecmp(lvl, "ERROR") == 0) { return log_level::LOG_ERROR; }
+  return log_level::LOG_INFO;
+}
+
+static inline log_level log_threshold()
+{
+  static log_level threshold = get_log_level_from_env();
+  return threshold;
+}
+
+static inline bool should_log(log_level level)
+{
+  return level >= log_threshold();
+}
+
+template<typename... Args>
+inline std::string string_format(const std::string& format, const Args&... args)
+{
+  int size_s = std::snprintf(nullptr, 0, format.c_str(), args...) + 1;
+  auto size = static_cast<size_t>(size_s);
+  if (size <= 0) return std::string();
+  std::unique_ptr<char[]> buf(new char[size]);
+  std::snprintf(buf.get(), size, format.c_str(), args...);
+  return std::string(buf.get(), buf.get() + size - 1);
+}
+
 inline void log_event(const json_iterator &iter, const char *type, std::string_view detail, int delta, int depth_delta) noexcept {
-  log_line(iter, "", type, detail, delta, depth_delta);
+  log_line(iter, "", type, detail, delta, depth_delta, log_level::LOG_INFO);
 }
 
 inline void log_value(const json_iterator &iter, token_position index, depth_t depth, const char *type, std::string_view detail) noexcept {
-  log_line(iter, index, depth, "", type, detail);
+  log_line(iter, index, depth, "", type, detail, log_level::LOG_INFO);
 }
 inline void log_value(const json_iterator &iter, const char *type, std::string_view detail, int delta, int depth_delta) noexcept {
-  log_line(iter, "", type, detail, delta, depth_delta);
+  log_line(iter, "", type, detail, delta, depth_delta, log_level::LOG_INFO);
 }
 
 inline void log_start_value(const json_iterator &iter, token_position index, depth_t depth, const char *type, std::string_view detail) noexcept {
-  log_line(iter, index, depth, "+", type, detail);
+  log_line(iter, index, depth, "+", type, detail, log_level::LOG_INFO);
   if (LOG_ENABLED) { log_depth++; }
 }
 inline void log_start_value(const json_iterator &iter, const char *type, int delta, int depth_delta) noexcept {
-  log_line(iter, "+", type, "", delta, depth_delta);
+  log_line(iter, "+", type, "", delta, depth_delta, log_level::LOG_INFO);
   if (LOG_ENABLED) { log_depth++; }
 }
 
 inline void log_end_value(const json_iterator &iter, const char *type, int delta, int depth_delta) noexcept {
   if (LOG_ENABLED) { log_depth--; }
-  log_line(iter, "-", type, "", delta, depth_delta);
+  log_line(iter, "-", type, "", delta, depth_delta, log_level::LOG_INFO);
 }
 
 inline void log_error(const json_iterator &iter, const char *error, const char *detail, int delta, int depth_delta) noexcept {
-  log_line(iter, "ERROR: ", error, detail, delta, depth_delta);
+  log_line(iter, "ERROR: ", error, detail, delta, depth_delta, log_level::LOG_ERROR);
 }
 inline void log_error(const json_iterator &iter, token_position index, depth_t depth, const char *error, const char *detail) noexcept {
-  log_line(iter, index, depth, "ERROR: ", error, detail);
+  log_line(iter, index, depth, "ERROR: ", error, detail, log_level::LOG_ERROR);
 }
 
 inline void log_event(const value_iterator &iter, const char *type, std::string_view detail, int delta, int depth_delta) noexcept {
@@ -71,7 +104,7 @@ inline void log_error(const value_iterator &iter, const char *error, const char
 }
 
 inline void log_headers() noexcept {
-  if (LOG_ENABLED) {
+  if (LOG_ENABLED && simdjson_unlikely(should_log(log_level::LOG_INFO))) {
     // Technically a static variable is not thread-safe, but if you are using threads
     // and logging... well...
     static bool displayed_hint{false};
@@ -121,11 +154,11 @@ inline void log_headers() noexcept {
   }
 }
 
-inline void log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta) noexcept {
-  log_line(iter, iter.position()+delta, depth_t(iter.depth()+depth_delta), title_prefix, title, detail);
+inline void log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta, log_level level) noexcept {
+  log_line(iter, iter.position()+delta, depth_t(iter.depth()+depth_delta), title_prefix, title, detail, level);
 }
-inline void log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail) noexcept {
-  if (LOG_ENABLED) {
+inline void log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail, log_level level) noexcept {
+  if (LOG_ENABLED && simdjson_unlikely(should_log(level))) {
     const int indent = depth*2;
     const auto buf = iter.token.buf;
     printf("| %*s%s%-*s ",
diff --git a/include/simdjson/generic/ondemand/logger.h b/include/simdjson/generic/ondemand/logger.h
index 928ffc0a..e7cc38c6 100644
--- a/include/simdjson/generic/ondemand/logger.h
+++ b/include/simdjson/generic/ondemand/logger.h
@@ -7,6 +7,11 @@ class value_iterator;
 
 namespace logger {
 
+enum class log_level : int32_t {
+  LOG_INFO = 0,
+  LOG_ERROR = 1
+};
+
 #if SIMDJSON_VERBOSE_LOGGING
   static constexpr const bool LOG_ENABLED = true;
 #else
@@ -16,9 +21,11 @@ namespace logger {
 // We do not want these functions to be 'really inlined' since real inlining is
 // for performance purposes and if you are using the loggers, you do not care about
 // performance (or should not).
+template<typename... Args>
+static inline std::string string_format(const std::string& format, const Args&... args);
 static inline void log_headers() noexcept;
-static inline void log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail) noexcept;
-static inline void log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta) noexcept;
+static inline void log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail, log_level level) noexcept;
+static inline void log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta, log_level level) noexcept;
 static inline void log_event(const json_iterator &iter, const char *type, std::string_view detail="", int delta=0, int depth_delta=0) noexcept;
 static inline void log_value(const json_iterator &iter, token_position index, depth_t depth, const char *type, std::string_view detail="") noexcept;
 static inline void log_value(const json_iterator &iter, const char *type, std::string_view detail="", int delta=-1, int depth_delta=0) noexcept;
diff --git a/include/simdjson/generic/ondemand/object-inl.h b/include/simdjson/generic/ondemand/object-inl.h
index 130da283..2e98c022 100644
--- a/include/simdjson/generic/ondemand/object-inl.h
+++ b/include/simdjson/generic/ondemand/object-inl.h
@@ -5,13 +5,23 @@ namespace ondemand {
 simdjson_inline simdjson_result<value> object::find_field_unordered(const std::string_view key) & noexcept {
   bool has_value;
   SIMDJSON_TRY( iter.find_field_unordered_raw(key).get(has_value) );
-  if (!has_value) { return NO_SUCH_FIELD; }
+  if (!has_value) {
+    auto key_str = std::string(key.data(), key.size());
+    auto msg = logger::string_format("Cannot find key: %s", key_str.c_str());
+    logger::log_error(iter, msg.c_str());
+    return NO_SUCH_FIELD;
+  }
   return value(iter.child());
 }
 simdjson_inline simdjson_result<value> object::find_field_unordered(const std::string_view key) && noexcept {
   bool has_value;
   SIMDJSON_TRY( iter.find_field_unordered_raw(key).get(has_value) );
-  if (!has_value) { return NO_SUCH_FIELD; }
+  if (!has_value) {
+    auto key_str = std::string(key.data(), key.size());
+    auto msg = logger::string_format("Cannot find key: %s", key_str.c_str());
+    logger::log_error(iter, msg.c_str());
+    return NO_SUCH_FIELD;
+  }
   return value(iter.child());
 }
 simdjson_inline simdjson_result<value> object::operator[](const std::string_view key) & noexcept {
@@ -23,13 +33,23 @@ simdjson_inline simdjson_result<value> object::operator[](const std::string_view
 simdjson_inline simdjson_result<value> object::find_field(const std::string_view key) & noexcept {
   bool has_value;
   SIMDJSON_TRY( iter.find_field_raw(key).get(has_value) );
-  if (!has_value) { return NO_SUCH_FIELD; }
+  if (!has_value) {
+    auto key_str = std::string(key.data(), key.size());
+    auto msg = logger::string_format("Cannot find key: %s", key_str.c_str());
+    logger::log_error(iter, msg.c_str());
+    return NO_SUCH_FIELD;
+  }
   return value(iter.child());
 }
 simdjson_inline simdjson_result<value> object::find_field(const std::string_view key) && noexcept {
   bool has_value;
   SIMDJSON_TRY( iter.find_field_raw(key).get(has_value) );
-  if (!has_value) { return NO_SUCH_FIELD; }
+  if (!has_value) {
+    auto key_str = std::string(key.data(), key.size());
+    auto msg = logger::string_format("Cannot find key: %s", key_str.c_str());
+    logger::log_error(iter, msg.c_str());
+    return NO_SUCH_FIELD;
+  }
   return value(iter.child());
 }
 
diff --git a/include/simdjson/generic/ondemand/token_iterator.h b/include/simdjson/generic/ondemand/token_iterator.h
index d85374a1..bd2d147b 100644
--- a/include/simdjson/generic/ondemand/token_iterator.h
+++ b/include/simdjson/generic/ondemand/token_iterator.h
@@ -116,8 +116,8 @@ protected:
   friend class json_iterator;
   friend class value_iterator;
   friend class object;
-  friend simdjson_inline void logger::log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta) noexcept;
-  friend simdjson_inline void logger::log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail) noexcept;
+  friend simdjson_inline void logger::log_line(const json_iterator &iter, const char *title_prefix, const char *title, std::string_view detail, int delta, int depth_delta, logger::log_level lvl) noexcept;
+  friend simdjson_inline void logger::log_line(const json_iterator &iter, token_position index, depth_t depth, const char *title_prefix, const char *title, std::string_view detail, logger::log_level lvl) noexcept;
 };
 
 } // namespace ondemand


Test patch:
diff --git a/tests/ondemand/CMakeLists.txt b/tests/ondemand/CMakeLists.txt
index 00f5336f..251c7977 100644
--- a/tests/ondemand/CMakeLists.txt
+++ b/tests/ondemand/CMakeLists.txt
@@ -3,6 +3,7 @@ link_libraries(simdjson)
 include_directories(..)
 add_subdirectory(compilation_failure_tests)
 add_cpp_test(ondemand_log_tests              LABELS ondemand acceptance per_implementation)
+add_cpp_test(ondemand_log_error_tests        LABELS ondemand acceptance per_implementation)
 add_cpp_test(ondemand_tostring_tests         LABELS ondemand acceptance per_implementation)
 add_cpp_test(ondemand_active_tests           LABELS ondemand acceptance per_implementation)
 add_cpp_test(ondemand_array_tests            LABELS ondemand acceptance per_implementation)
diff --git a/tests/ondemand/ondemand_log_error_tests.cpp b/tests/ondemand/ondemand_log_error_tests.cpp
new file mode 100644
index 00000000..ad249c90
--- /dev/null
+++ b/tests/ondemand/ondemand_log_error_tests.cpp
@@ -0,0 +1,67 @@
+#define SIMDJSON_VERBOSE_LOGGING 1
+#include "simdjson.h"
+#include "test_ondemand.h"
+
+#include <iostream>
+#include <string>
+#include <stdlib.h>
+
+using namespace simdjson;
+
+namespace log_error_tests {
+#if SIMDJSON_EXCEPTIONS
+
+using namespace std;
+
+bool tape_error()
+{
+  TEST_START();
+  auto json = R"( {"a", "hello"} )"_padded;
+  ondemand::parser parser;
+  try {
+    ondemand::document doc = parser.iterate(json);
+    std::cout << doc["a"] << std::endl;
+    TEST_FAIL("Should have thrown an exception!")
+  } catch (simdjson_error& e) {
+    ASSERT_ERROR(e.error(), TAPE_ERROR);
+  }
+  TEST_SUCCEED();
+}
+
+bool no_such_field()
+{
+  TEST_START();
+  auto json = R"( {"a": "hello"} )"_padded;
+  ondemand::parser parser;
+  try {
+    ondemand::document doc = parser.iterate(json);
+    std::cout << doc["missing_key"] << std::endl;
+    TEST_FAIL("Should have thrown an exception!")
+  } catch (simdjson_error& e) {
+    ASSERT_ERROR(e.error(), NO_SUCH_FIELD);
+  }
+  TEST_SUCCEED();
+}
+#endif // SIMDJSON_EXCEPTIONS
+
+bool run()
+{
+  SIMDJSON_PUSH_DISABLE_WARNINGS
+  SIMDJSON_DISABLE_DEPRECATED_WARNING // Disable CRT_SECURE warning on MSVC: manually verified this is safe
+  std::string str = "SIMDJSON_LOG_LEVEL=ERROR";
+  putenv(str.data());
+  bool rc =
+#if SIMDJSON_EXCEPTIONS
+            tape_error() &&
+            no_such_field() &&
+#endif // #if SIMDJSON_EXCEPTIONS
+            true;
+  SIMDJSON_POP_DISABLE_WARNINGS
+  return rc;
+}
+
+}
+
+int main(int argc, char *argv[]) {
+  return test_main(argc, argv, log_error_tests::run);
+}