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

@@ -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
 -------
 

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;

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

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.