From 049e064e28df1e2eb8169ac5d6ba7165f8e2f37d Mon Sep 17 00:00:00 2001
From: Tatsuhiro Tsujikawa <tatsuhiro.t@gmail.com>
Date: Sun, 18 Dec 2016 22:56:24 +0900
Subject: [PATCH] nghttpx: New error log format

To debug multi threaded configuration easier, we added current PID and
thread ID to error log.  Previously, we didn't add date and time if
log level is NOTICE.  In this change, we always write date and time
regardless of log level.
---
 doc/nghttpx.h2r         | 27 +++++++++++++++++++++++++++
 src/shrpx_log.cc        | 22 +++++++---------------
 src/shrpx_log_config.cc | 15 ++++++++++++++-
 src/shrpx_log_config.h  |  4 ++++
 4 files changed, 52 insertions(+), 16 deletions(-)

diff --git a/doc/nghttpx.h2r b/doc/nghttpx.h2r
index 74565e7e..7159e512 100644
--- a/doc/nghttpx.h2r
+++ b/doc/nghttpx.h2r
@@ -41,6 +41,33 @@ FILES
   :option:`--conf` option cannot be used in the configuration file and
   will be ignored if specified.
 
+Error log
+  Error log is written to stderr by default.  It can be configured
+  using :option:`--errorlog-file`.  The format of log message is as
+  follows:
+
+  <datetime> <master-pid> <current-pid> <thread-id> <level> (<filename>:<line>) <msg>
+
+  <datetime>
+    It is a conbination of date and time when the log is written.  It
+    is in ISO 8601 format.
+
+  <master-pid>
+    It is a master process ID.
+
+  <current-pid>
+    It is a process ID which writes this log.
+
+  <thread-id>
+    It is a thread ID which writes this log.  It would be unique
+    within <current-pid>.
+
+  <filename> and <line>
+    They are source file name, and line number which produce this log.
+
+  <msg>
+    It is a log message body.
+
 SIGNALS
 -------
 
diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc
index 00f55d7e..330d539b 100644
--- a/src/shrpx_log.cc
+++ b/src/shrpx_log.cc
@@ -138,22 +138,14 @@ Log::~Log() {
   auto tty = lgconf->errorlog_tty;
 
   lgconf->update_tstamp(std::chrono::system_clock::now());
-  auto &time_local = lgconf->time_local;
 
-  if (severity_ == NOTICE) {
-    rv =
-        snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s\n", time_local.c_str(),
-                 config->pid, tty ? SEVERITY_COLOR[severity_] : "",
-                 SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
-                 stream_.str().c_str());
-  } else {
-    rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s%s:%d%s %s\n",
-                  time_local.c_str(), config->pid,
-                  tty ? SEVERITY_COLOR[severity_] : "",
-                  SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
-                  tty ? "\033[1;30m" : "", filename_, linenum_,
-                  tty ? "\033[0m" : "", stream_.str().c_str());
-  }
+  // Error log format: <datetime> <master-pid> <current-pid>
+  // <thread-id> <level> (<filename>:<line>) <msg>
+  rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %s\n",
+                lgconf->time_iso8601.c_str(), config->pid, lgconf->pid,
+                lgconf->thread_id.c_str(), tty ? SEVERITY_COLOR[severity_] : "",
+                SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
+                filename_, linenum_, stream_.str().c_str());
 
   if (rv < 0) {
     return;
diff --git a/src/shrpx_log_config.cc b/src/shrpx_log_config.cc
index 57e97912..93735cce 100644
--- a/src/shrpx_log_config.cc
+++ b/src/shrpx_log_config.cc
@@ -23,6 +23,12 @@
  * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  */
 #include "shrpx_log_config.h"
+
+#include <unistd.h>
+
+#include <thread>
+#include <sstream>
+
 #include "util.h"
 
 using namespace nghttp2;
@@ -30,7 +36,14 @@ using namespace nghttp2;
 namespace shrpx {
 
 LogConfig::LogConfig()
-    : accesslog_fd(-1), errorlog_fd(-1), errorlog_tty(false) {}
+    : pid(getpid()), accesslog_fd(-1), errorlog_fd(-1), errorlog_tty(false) {
+  auto tid = std::this_thread::get_id();
+  auto tid_hash =
+      util::hash32(StringRef{reinterpret_cast<uint8_t *>(&tid),
+                             reinterpret_cast<uint8_t *>(&tid) + sizeof(tid)});
+  thread_id = util::format_hex(reinterpret_cast<uint8_t *>(&tid_hash),
+                               sizeof(tid_hash));
+}
 
 #ifndef NOTHREADS
 #ifdef HAVE_THREAD_LOCAL
diff --git a/src/shrpx_log_config.h b/src/shrpx_log_config.h
index 2f37f602..8fa44a9a 100644
--- a/src/shrpx_log_config.h
+++ b/src/shrpx_log_config.h
@@ -27,6 +27,8 @@
 
 #include "shrpx.h"
 
+#include <sys/types.h>
+
 #include <chrono>
 
 #include "template.h"
@@ -40,9 +42,11 @@ struct LogConfig {
   std::array<char, sizeof("03/Jul/2014:00:19:38 +0900")> time_local_buf;
   std::array<char, sizeof("2014-11-15T12:58:24.741+09:00")> time_iso8601_buf;
   std::array<char, sizeof("Mon, 10 Oct 2016 10:25:58 GMT")> time_http_buf;
+  std::string thread_id;
   StringRef time_local;
   StringRef time_iso8601;
   StringRef time_http;
+  pid_t pid;
   int accesslog_fd;
   int errorlog_fd;
   // true if errorlog_fd is referring to a terminal.