Alow prefixing log output with a timestamp.

When AppTimestampLog is set to 1 all output to stdout and stderr will be
prefixed with a millisecond-precision ISO8601 timestamp.

Timestamp prefixing implies online rotation mode.  It should be
considered experimental as it requires splitting input lines by LF with
no way of knowing for certain that the input stream actually is
line-based.

Thanks Nicolas Ducrocq.

diff --git a/README.txt b/README.txt
index 00440f9..fc5121e 100644 (file)
--- a/README.txt
+++ b/README.txt
@@ -371,6 +371,21 @@ error-prone than simply redirecting the I/O streams before launching the
 application.  Therefore online rotation is not enabled by default.\r
 \r
 \r
+Timestamping output\r
+-------------------\r
+When redirecting output, NSSM can prefix each line of output with a\r
+millisecond-precision timestamp, for example:\r
+\r
+    2016-09-06 10:17:09.451 Pipeline main started\r
+\r
+To enable timestamp prefixing, set AppTimestampLog to a non-zero value.\r
+\r
+The prefix applies to both stdout and stderr.  Prefixing requires\r
+intercepting the application's I/O in the same way that online rotation\r
+does.  If log rotation and timestamp prefixing are both enabled, the\r
+rotation will be online.\r
+\r
+\r
 Environment variables\r
 ---------------------\r
 NSSM can replace or append to the managed application's environment.  Two\r
@@ -1006,6 +1021,7 @@ Thanks to Nabil Redmann for suggesting redirecting hooks' output.
 Thanks to Bader Aldurai for suggesting the process tree.\r
 Thanks to Christian Long for suggesting virtual accounts.\r
 Thanks to Marcin Lewandowski for spotting a bug appending to large files.\r
+Thanks to Nicolas Ducrocq for suggesting timestamping redirected output.\r
 \r
 Licence\r
 -------\r

diff --git a/gui.cpp b/gui.cpp
index 0fa11f4..9c4d712 100644 (file)
--- a/gui.cpp
+++ b/gui.cpp
@@ -180,6 +180,7 @@ int nssm_gui(int resource, nssm_service_t *service) {
     SetDlgItemText(tablist[NSSM_TAB_IO], IDC_STDIN, service->stdin_path);\r
     SetDlgItemText(tablist[NSSM_TAB_IO], IDC_STDOUT, service->stdout_path);\r
     SetDlgItemText(tablist[NSSM_TAB_IO], IDC_STDERR, service->stderr_path);\r
+    if (service->timestamp_log) SendDlgItemMessage(tablist[NSSM_TAB_IO], IDC_TIMESTAMP, BM_SETCHECK, BST_CHECKED, 0);\r
 \r
     /* Rotation tab. */\r
     if (service->stdout_disposition == CREATE_ALWAYS) SendDlgItemMessage(tablist[NSSM_TAB_ROTATION], IDC_TRUNCATE, BM_SETCHECK, BST_CHECKED, 0);\r
@@ -676,6 +677,8 @@ int configure(HWND window, nssm_service_t *service, nssm_service_t *orig_service
   check_io(window, _T("stdin"), service->stdin_path, _countof(service->stdin_path), IDC_STDIN);\r
   check_io(window, _T("stdout"), service->stdout_path, _countof(service->stdout_path), IDC_STDOUT);\r
   check_io(window, _T("stderr"), service->stderr_path, _countof(service->stderr_path), IDC_STDERR);\r
+  if (SendDlgItemMessage(tablist[NSSM_TAB_IO], IDC_TIMESTAMP, BM_GETCHECK, 0, 0) & BST_CHECKED) service->timestamp_log = true;\r
+  else service->timestamp_log = false;\r
 \r
   /* Override stdout and/or stderr. */\r
   if (SendDlgItemMessage(tablist[NSSM_TAB_ROTATION], IDC_TRUNCATE, BM_GETCHECK, 0, 0) & BST_CHECKED) {\r
@@ -1248,6 +1251,9 @@ INT_PTR CALLBACK nssm_dlg(HWND window, UINT message, WPARAM w, LPARAM l) {
       tablist[NSSM_TAB_IO] = dialog(MAKEINTRESOURCE(IDD_IO), window, tab_dlg);\r
       ShowWindow(tablist[NSSM_TAB_IO], SW_HIDE);\r
 \r
+      /* Set defaults. */\r
+      SendDlgItemMessage(tablist[NSSM_TAB_IO], IDC_TIMESTAMP, BM_SETCHECK, BST_UNCHECKED, 0);\r
+\r
       /* Rotation tab. */\r
       tab.pszText = message_string(NSSM_GUI_TAB_ROTATION);\r
       tab.cchTextMax = (int) _tcslen(tab.pszText) + 1;\r

diff --git a/io.cpp b/io.cpp
index 48611b0..dd2641c 100644 (file)
--- a/io.cpp
+++ b/io.cpp
@@ -3,6 +3,8 @@
 #define COMPLAINED_READ (1 << 0)\r
 #define COMPLAINED_WRITE (1 << 1)\r
 #define COMPLAINED_ROTATE (1 << 2)\r
+#define TIMESTAMP_FORMAT "%04u-%02u-%02u %02u:%02u:%02u.%03u: "\r
+#define TIMESTAMP_LEN 25\r
 \r
 static int dup_handle(HANDLE source_handle, HANDLE *dest_handle_ptr, TCHAR *source_description, TCHAR *dest_description, unsigned long flags) {\r
   if (! dest_handle_ptr) return 1;\r
@@ -23,7 +25,7 @@ static int dup_handle(HANDLE source_handle, HANDLE *dest_handle_ptr, TCHAR *sour
   pipe_handle:  stdout of application\r
   write_handle: to file\r
 */\r
-static HANDLE create_logging_thread(TCHAR *service_name, TCHAR *path, unsigned long sharing, unsigned long disposition, unsigned long flags, HANDLE *read_handle_ptr, HANDLE *pipe_handle_ptr, HANDLE *write_handle_ptr, unsigned long rotate_bytes_low, unsigned long rotate_bytes_high, unsigned long rotate_delay, unsigned long *tid_ptr, unsigned long *rotate_online, bool copy_and_truncate) {\r
+static HANDLE create_logging_thread(TCHAR *service_name, TCHAR *path, unsigned long sharing, unsigned long disposition, unsigned long flags, HANDLE *read_handle_ptr, HANDLE *pipe_handle_ptr, HANDLE *write_handle_ptr, unsigned long rotate_bytes_low, unsigned long rotate_bytes_high, unsigned long rotate_delay, unsigned long *tid_ptr, unsigned long *rotate_online, bool timestamp_log, bool copy_and_truncate) {\r
   *tid_ptr = 0;\r
 \r
   /* Pipe between application's stdout/stderr and our logging handle. */\r
@@ -58,6 +60,8 @@ static HANDLE create_logging_thread(TCHAR *service_name, TCHAR *path, unsigned l
   logger->write_handle = *write_handle_ptr;\r
   logger->size = (__int64) size.QuadPart;\r
   logger->tid_ptr = tid_ptr;\r
+  logger->timestamp_log = timestamp_log;\r
+  logger->line_length = 0;\r
   logger->rotate_online = rotate_online;\r
   logger->rotate_delay = rotate_delay;\r
   logger->copy_and_truncate = copy_and_truncate;\r
@@ -323,7 +327,7 @@ int get_output_handles(nssm_service_t *service, STARTUPINFO *si) {
 \r
     if (service->use_stdout_pipe) {\r
       service->stdout_pipe = si->hStdOutput = 0;\r
-      service->stdout_thread = create_logging_thread(service->name, service->stdout_path, service->stdout_sharing, service->stdout_disposition, service->stdout_flags, &service->stdout_pipe, &service->stdout_si, &stdout_handle, service->rotate_bytes_low, service->rotate_bytes_high, service->rotate_delay, &service->stdout_tid, &service->rotate_stdout_online, service->stdout_copy_and_truncate);\r
+      service->stdout_thread = create_logging_thread(service->name, service->stdout_path, service->stdout_sharing, service->stdout_disposition, service->stdout_flags, &service->stdout_pipe, &service->stdout_si, &stdout_handle, service->rotate_bytes_low, service->rotate_bytes_high, service->rotate_delay, &service->stdout_tid, &service->rotate_stdout_online, service->timestamp_log, service->stdout_copy_and_truncate);\r
       if (! service->stdout_thread) {\r
         CloseHandle(service->stdout_pipe);\r
         CloseHandle(service->stdout_si);\r
@@ -360,7 +364,7 @@ int get_output_handles(nssm_service_t *service, STARTUPINFO *si) {
 \r
       if (service->use_stderr_pipe) {\r
         service->stderr_pipe = si->hStdError = 0;\r
-        service->stderr_thread = create_logging_thread(service->name, service->stderr_path, service->stderr_sharing, service->stderr_disposition, service->stderr_flags, &service->stderr_pipe, &service->stderr_si, &stderr_handle, service->rotate_bytes_low, service->rotate_bytes_high, service->rotate_delay, &service->stderr_tid, &service->rotate_stderr_online, service->stderr_copy_and_truncate);\r
+        service->stderr_thread = create_logging_thread(service->name, service->stderr_path, service->stderr_sharing, service->stderr_disposition, service->stderr_flags, &service->stderr_pipe, &service->stderr_si, &stderr_handle, service->rotate_bytes_low, service->rotate_bytes_high, service->rotate_delay, &service->stderr_tid, &service->rotate_stderr_online, service->timestamp_log, service->stderr_copy_and_truncate);\r
         if (! service->stderr_thread) {\r
           CloseHandle(service->stderr_pipe);\r
           CloseHandle(service->stderr_si);\r
@@ -533,6 +537,69 @@ complain_write:
   return ret;\r
 }\r
 \r
+/* Note that the timestamp is created in UTF-8. */\r
+static inline int write_timestamp(logger_t *logger, unsigned long charsize, unsigned long *out, int *complained) {\r
+  char timestamp[TIMESTAMP_LEN + 1];\r
+\r
+  SYSTEMTIME now;\r
+  GetSystemTime(&now);\r
+  _snprintf_s(timestamp, _countof(timestamp), _TRUNCATE, TIMESTAMP_FORMAT, now.wYear, now.wMonth, now.wDay, now.wHour, now.wMinute, now.wSecond, now.wMilliseconds);\r
+\r
+  if (charsize == sizeof(char)) return try_write(logger, (void *) timestamp, TIMESTAMP_LEN, out, complained);\r
+\r
+  wchar_t *utf16;\r
+  unsigned long utf16len;\r
+  if (to_utf16(timestamp, &utf16, &utf16len)) return -1;\r
+  int ret = try_write(logger, (void *) *utf16, utf16len * sizeof(wchar_t), out, complained);\r
+  HeapFree(GetProcessHeap(), 0, utf16);\r
+  return ret;\r
+}\r
+\r
+static int write_with_timestamp(logger_t *logger, void *address, unsigned long bufsize, unsigned long *out, int *complained, unsigned long charsize) {\r
+  if (logger->timestamp_log) {\r
+    unsigned long log_out;\r
+    int log_complained;\r
+    unsigned long timestamp_out = 0;\r
+    int timestamp_complained;\r
+    if (! logger->line_length) {\r
+      write_timestamp(logger, charsize, &timestamp_out, &timestamp_complained);\r
+      logger->line_length += (__int64) timestamp_out;\r
+      *out += timestamp_out;\r
+      *complained |= timestamp_complained;\r
+    }\r
+\r
+    unsigned long i;\r
+    void *line = address;\r
+    unsigned long offset = 0;\r
+    int ret;\r
+    for (i = 0; i < bufsize; i++) {\r
+      if (((char *) address)[i] == '\n') {\r
+        ret = try_write(logger, line, i - offset + 1, &log_out, &log_complained);\r
+        line = (void *) ((char *) line + i - offset + 1);\r
+        logger->line_length = 0LL;\r
+        *out += log_out;\r
+        *complained |= log_complained;\r
+        offset = i + 1;\r
+        if (offset < bufsize) {\r
+          write_timestamp(logger, charsize, &timestamp_out, &timestamp_complained);\r
+          logger->line_length += (__int64) timestamp_out;\r
+          *out += timestamp_out;\r
+          *complained |= timestamp_complained;\r
+        }\r
+      }\r
+    }\r
+\r
+    if (offset < bufsize) {\r
+      ret = try_write(logger, line, bufsize - offset, &log_out, &log_complained);\r
+      *out += log_out;\r
+      *complained |= log_complained;\r
+    }\r
+\r
+    return ret;\r
+  }\r
+  else return try_write(logger, address, bufsize, out, complained);\r
+}\r
+\r
 /* Wrapper to be called in a new thread for logging. */\r
 unsigned long WINAPI log_and_rotate(void *arg) {\r
   logger_t *logger = (logger_t *) arg;\r
@@ -650,9 +717,9 @@ unsigned long WINAPI log_and_rotate(void *arg) {
       }\r
     }\r
 \r
+    if (! size || logger->timestamp_log) if (! charsize) charsize = guess_charsize(address, in);\r
     if (! size) {\r
       /* Write a BOM to the new file. */\r
-      if (! charsize) charsize = guess_charsize(address, in);\r
       if (charsize == sizeof(wchar_t)) write_bom(logger, &out);\r
       size += (__int64) out;\r
     }\r
@@ -660,7 +727,7 @@ unsigned long WINAPI log_and_rotate(void *arg) {
     /* Write the data, if any. */\r
     if (! in) continue;\r
 \r
-    ret = try_write(logger, address, in, &out, &complained);\r
+    ret = write_with_timestamp(logger, address, in, &out, &complained, charsize);\r
     size += (__int64) out;\r
     if (ret < 0) {\r
       close_handle(&logger->read_handle);\r

diff --git a/nssm.rc b/nssm.rc
index 9f61384..8c0d377 100644 (file)
Binary files a/nssm.rc and b/nssm.rc differ

diff --git a/registry.cpp b/registry.cpp
index 93c034d..1b85af5 100644 (file)
--- a/registry.cpp
+++ b/registry.cpp
@@ -166,6 +166,8 @@ int create_parameters(nssm_service_t *service, bool editing) {
     if (service->stderr_copy_and_truncate) set_createfile_parameter(key, NSSM_REG_STDERR, NSSM_REG_STDIO_COPY_AND_TRUNCATE, 1);\r
     else if (editing) delete_createfile_parameter(key, NSSM_REG_STDERR, NSSM_REG_STDIO_COPY_AND_TRUNCATE);\r
   }\r
+  if (service->timestamp_log) set_number(key, NSSM_REG_TIMESTAMP_LOG, 1);\r
+  else if (editing) RegDeleteValue(key, NSSM_REG_TIMESTAMP_LOG);\r
   if (service->hook_share_output_handles) set_number(key, NSSM_REG_HOOK_SHARE_OUTPUT_HANDLES, 1);\r
   else if (editing) RegDeleteValue(key, NSSM_REG_HOOK_SHARE_OUTPUT_HANDLES);\r
   if (service->rotate_files) set_number(key, NSSM_REG_ROTATE, 1);\r
@@ -828,9 +830,17 @@ int get_parameters(nssm_service_t *service, STARTUPINFO *si) {
     else service->rotate_stdout_online = service->rotate_stderr_online = false;\r
   }\r
   else service->rotate_stdout_online = service->rotate_stderr_online = false;\r
+  /* Log timestamping requires a logging thread.*/\r
+  unsigned long timestamp_log;\r
+  if (get_number(key, NSSM_REG_TIMESTAMP_LOG, &timestamp_log, false) == 1) {\r
+    if (timestamp_log) service->timestamp_log = true;\r
+    else service->timestamp_log = false;\r
+  }\r
+  else service->timestamp_log = false;\r
+\r
   /* Hook I/O sharing and online rotation need a pipe. */\r
-  service->use_stdout_pipe = service->rotate_stdout_online || hook_share_output_handles;\r
-  service->use_stderr_pipe = service->rotate_stderr_online || hook_share_output_handles;\r
+  service->use_stdout_pipe = service->rotate_stdout_online || service->timestamp_log || hook_share_output_handles;\r
+  service->use_stderr_pipe = service->rotate_stderr_online || service->timestamp_log || hook_share_output_handles;\r
   if (get_number(key, NSSM_REG_ROTATE_SECONDS, &service->rotate_seconds, false) != 1) service->rotate_seconds = 0;\r
   if (get_number(key, NSSM_REG_ROTATE_BYTES_LOW, &service->rotate_bytes_low, false) != 1) service->rotate_bytes_low = 0;\r
   if (get_number(key, NSSM_REG_ROTATE_BYTES_HIGH, &service->rotate_bytes_high, false) != 1) service->rotate_bytes_high = 0;\r

diff --git a/registry.h b/registry.h
index ad7cd7a..25ba091 100644 (file)
--- a/registry.h
+++ b/registry.h
@@ -32,6 +32,7 @@
 #define NSSM_REG_ROTATE_BYTES_LOW _T("AppRotateBytes")\r
 #define NSSM_REG_ROTATE_BYTES_HIGH _T("AppRotateBytesHigh")\r
 #define NSSM_REG_ROTATE_DELAY _T("AppRotateDelay")\r
+#define NSSM_REG_TIMESTAMP_LOG _T("AppTimestampLog")\r
 #define NSSM_REG_PRIORITY _T("AppPriority")\r
 #define NSSM_REG_AFFINITY _T("AppAffinity")\r
 #define NSSM_REG_NO_CONSOLE _T("AppNoConsole")\r

diff --git a/resource.h b/resource.h
index 3dcf6db..f4dd3d5 100644 (file)
--- a/resource.h
+++ b/resource.h
@@ -72,6 +72,7 @@
 #define IDC_BROWSE_HOOK                 1051\r
 #define IDC_REDIRECT_HOOK               1052\r
 #define IDC_VIRTUAL_SERVICE             1053\r
+#define IDC_TIMESTAMP                   1054\r
 \r
 // Next default values for new objects\r
 // \r
@@ -79,7 +80,7 @@
 #ifndef APSTUDIO_READONLY_SYMBOLS\r
 #define _APS_NEXT_RESOURCE_VALUE        117\r
 #define _APS_NEXT_COMMAND_VALUE         40001\r
-#define _APS_NEXT_CONTROL_VALUE         1054\r
+#define _APS_NEXT_CONTROL_VALUE         1055\r
 #define _APS_NEXT_SYMED_VALUE           101\r
 #endif\r
 #endif\r

diff --git a/service.h b/service.h
index a8e0bcf..fb8a160 100644 (file)
--- a/service.h
+++ b/service.h
@@ -77,6 +77,7 @@ typedef struct {
   unsigned long stderr_tid;\r
   bool hook_share_output_handles;\r
   bool rotate_files;\r
+  bool timestamp_log;\r
   bool stdout_copy_and_truncate;\r
   bool stderr_copy_and_truncate;\r
   unsigned long rotate_stdout_online;\r

diff --git a/settings.cpp b/settings.cpp
index 9e5f666..e72430f 100644 (file)
--- a/settings.cpp
+++ b/settings.cpp
@@ -1435,6 +1435,7 @@ settings_t settings[] = {
   { NSSM_REG_ROTATE_BYTES_LOW, REG_DWORD, 0, false, 0, setting_set_number, setting_get_number, 0 },\r
   { NSSM_REG_ROTATE_BYTES_HIGH, REG_DWORD, 0, false, 0, setting_set_number, setting_get_number, 0 },\r
   { NSSM_REG_ROTATE_DELAY, REG_DWORD, (void *) NSSM_ROTATE_DELAY, false, 0, setting_set_number, setting_get_number, 0 },\r
+  { NSSM_REG_TIMESTAMP_LOG, REG_DWORD, 0, false, 0, setting_set_number, setting_get_number, 0 },\r
   { NSSM_NATIVE_DEPENDONGROUP, REG_MULTI_SZ, NULL, true, ADDITIONAL_CRLF, native_set_dependongroup, native_get_dependongroup, native_dump_dependongroup },\r
   { NSSM_NATIVE_DEPENDONSERVICE, REG_MULTI_SZ, NULL, true, ADDITIONAL_CRLF, native_set_dependonservice, native_get_dependonservice, native_dump_dependonservice },\r
   { NSSM_NATIVE_DESCRIPTION, REG_SZ, _T(""), true, 0, native_set_description, native_get_description, 0 },\r