fix(core): fixed logging and status reporting for windows service mode… (#1969)

core/src/main/bin/questdb.sh

@@ -175,7 +175,7 @@ function start {
     -ea -Dnoebug
     -XX:+UnlockExperimentalVMOptions
     -XX:+AlwaysPreTouch
-    -XX:+UseParallelOldGC
+    -XX:+UseParallelGC
     "
 
     JAVA_MAIN="io.questdb/io.questdb.ServerMain"

core/src/main/java/io/questdb/ServerMain.java

@@ -78,14 +78,16 @@ public class ServerMain {
         }
 
         final CharSequenceObjHashMap<String> optHash = hashArgs(args);
-
-        final Log log = LogFactory.getLog("server-main");
         // expected flags:
         // -d <root dir> = sets root directory
         // -f = forces copy of site to root directory even if site exists
         // -n = disables handling of HUP signal
 
         final String rootDirectory = optHash.get("-d");
+
+        LogFactory.configureFromSystemProperties(LogFactory.INSTANCE, null, rootDirectory);
+        final Log log = LogFactory.getLog("server-main");
+
         extractSite(buildInformation, rootDirectory, log);
         final Properties properties = new Properties();
         final String configurationFileName = "/server.conf";
@@ -378,7 +380,8 @@ public class ServerMain {
         }
     }
 
-    private static void extractSite(BuildInformation buildInformation, String dir, Log log) throws IOException {
+    //made package level for testing only  
+    static void extractSite(BuildInformation buildInformation, String dir, Log log) throws IOException {
         final String publicZip = "/io/questdb/site/public.zip";
         final String publicDir = dir + "/public";
         final byte[] buffer = new byte[1024 * 1024];
@@ -452,6 +455,7 @@ public class ServerMain {
         copyConfResource(dir, false, buffer, "conf/date.formats", log);
         copyConfResource(dir, true, buffer, "conf/mime.types", log);
         copyConfResource(dir, false, buffer, "conf/server.conf", log);
+        copyConfResource(dir, false, buffer, "conf/log.conf", log);
     }
 
     private static void copyConfResource(String dir, boolean force, byte[] buffer, String res, Log log) throws IOException {
@@ -605,4 +609,4 @@ public class ServerMain {
     ) {
         workerPool.start(log);
     }
-}
\ No newline at end of file
+}

core/src/main/java/io/questdb/log/LogFactory.java

@@ -35,6 +35,7 @@ import org.jetbrains.annotations.TestOnly;
 import java.io.*;
 import java.lang.reflect.Constructor;
 import java.lang.reflect.Field;
+import java.nio.file.Paths;
 import java.util.Comparator;
 import java.util.Properties;
 
@@ -47,10 +48,18 @@ public class LogFactory implements Closeable {
 
     private static final int DEFAULT_QUEUE_DEPTH = 1024;
     private static final int DEFAULT_MSG_SIZE = 4 * 1024;
-    private static final String DEFAULT_CONFIG = "/log-stdout.conf";
+
+    //name of default logging configuration file (in jar and in $root/conf/ dir )
+    public static final String DEFAULT_CONFIG_NAME = "log.conf";
+    private static final String DEFAULT_CONFIG = "/io/questdb/site/conf/" + DEFAULT_CONFIG_NAME;
+
+    //placeholder that can be used in log.conf to point to $root/log/ dir 
+    public static final String LOG_DIR_VAR = "${log.dir}";
+
     private static final String EMPTY_STR = "";
     private static final CharSequenceHashSet reserved = new CharSequenceHashSet();
     private static final LengthDescendingComparator LDC = new LengthDescendingComparator();
+
     private final CharSequenceObjHashMap<ScopeConfiguration> scopeConfigMap = new CharSequenceObjHashMap<>();
     private final ObjList<ScopeConfiguration> scopeConfigs = new ObjList<>();
     private final ObjHashSet<LogWriter> jobs = new ObjHashSet<>();
@@ -70,7 +79,7 @@ public class LogFactory implements Closeable {
         this.clock = clock;
     }
 
-    public static void configureFromProperties(LogFactory factory, Properties properties, WorkerPool workerPool) {
+    public static void configureFromProperties(LogFactory factory, Properties properties, WorkerPool workerPool, String logDir) {
 
         factory.workerPool = workerPool;
         String writers = getProperty(properties, "writers");
@@ -101,7 +110,7 @@ public class LogFactory implements Closeable {
         }
 
         for (String w : writers.split(",")) {
-            LogWriterConfig conf = createWriter(properties, w.trim());
+            LogWriterConfig conf = createWriter(properties, w.trim(), logDir);
             if (conf != null) {
                 factory.add(conf);
             }
@@ -115,33 +124,69 @@ public class LogFactory implements Closeable {
     }
 
     public static void configureFromSystemProperties(LogFactory factory, WorkerPool workerPool) {
+        configureFromSystemProperties(factory, workerPool, null);
+    }
+
+    public static void configureFromSystemProperties(LogFactory factory, WorkerPool workerPool, String rootDir) {
         String conf = System.getProperty(CONFIG_SYSTEM_PROPERTY);
         if (conf == null) {
             conf = DEFAULT_CONFIG;
         }
-        try (InputStream is = LogFactory.class.getResourceAsStream(conf)) {
-            if (is != null) {
-                Properties properties = new Properties();
-                properties.load(is);
-                configureFromProperties(factory, properties, workerPool);
-            } else {
-                File f = new File(conf);
-                if (f.canRead()) {
-                    try (FileInputStream fis = new FileInputStream(f)) {
-                        Properties properties = new Properties();
-                        properties.load(fis);
-                        configureFromProperties(factory, properties, workerPool);
+
+        boolean initialized = false;
+        String logDir = rootDir != null ? Paths.get(rootDir, "log").toString() : "log";
+        File logDirFile = new File(logDir);
+
+        if (!logDirFile.exists() && logDirFile.mkdir()) {
+            System.err.printf("Created log directory: %s%n", logDir);
+        }
+
+        if (rootDir != null && DEFAULT_CONFIG.equals(conf)) {
+            String logPath = Paths.get(rootDir, "conf", DEFAULT_CONFIG_NAME).toString();
+            File f = new File(logPath);
+            if (f.isFile() && f.canRead()) {
+                System.err.printf("Reading log configuration from %s%n", logPath);
+                try (FileInputStream fis = new FileInputStream(logPath)) {
+                    Properties properties = new Properties();
+                    properties.load(fis);
+                    configureFromProperties(factory, properties, workerPool, logDir);
+                    System.err.printf("Log configuration loaded from: %s%n", logPath);
+                    initialized = true;
+                } catch (IOException e) {
+                    throw new LogError("Cannot read " + logPath, e);
+                }
+            }
+        }
+
+        if (!initialized) {
+            //in this order of initialization specifying -Dout might end up using internal jar resources ...   
+            try (InputStream is = LogFactory.class.getResourceAsStream(conf)) {
+                if (is != null) {
+                    Properties properties = new Properties();
+                    properties.load(is);
+                    configureFromProperties(factory, properties, workerPool, logDir);
+                    System.err.println("Log configuration loaded from default internal file.");
+                } else {
+                    File f = new File(conf);
+                    if (f.canRead()) {
+                        try (FileInputStream fis = new FileInputStream(f)) {
+                            Properties properties = new Properties();
+                            properties.load(fis);
+                            configureFromProperties(factory, properties, workerPool, logDir);
+                            System.err.printf("Log configuration loaded from: %s%n", conf);
+                        }
+                    } else {
+                        factory.configureDefaultWriter();
+                        System.err.println("Log configuration loaded loaded using factory defaults.");
                     }
+                }
+            } catch (IOException e) {
+                if (!DEFAULT_CONFIG.equals(conf)) {
+                    throw new LogError("Cannot read " + conf, e);
                 } else {
                     factory.configureDefaultWriter();
                 }
             }
-        } catch (IOException e) {
-            if (!DEFAULT_CONFIG.equals(conf)) {
-                throw new LogError("Cannot read " + conf, e);
-            } else {
-                factory.configureDefaultWriter();
-            }
         }
         factory.startThread();
     }
@@ -331,8 +376,8 @@ public class LogFactory implements Closeable {
     }
 
     @SuppressWarnings("rawtypes")
-    private static LogWriterConfig createWriter(final Properties properties, String w) {
-        final String writer = "w." + w + '.';
+    private static LogWriterConfig createWriter(final Properties properties, String writerName, String logDir) {
+        final String writer = "w." + writerName + '.';
         final String clazz = getProperty(properties, writer + "class");
         final String levelStr = getProperty(properties, writer + "level");
         final String scope = getProperty(properties, writer + "scope");
@@ -401,7 +446,13 @@ public class LogFactory implements Closeable {
                         try {
                             Field f = cl.getDeclaredField(p);
                             if (f.getType() == String.class) {
-                                Unsafe.getUnsafe().putObject(w1, Unsafe.getUnsafe().objectFieldOffset(f), getProperty(properties, n));
+
+                                String value = getProperty(properties, n);
+                                if (logDir != null && value.contains(LOG_DIR_VAR)) {
+                                    value = value.replace(LOG_DIR_VAR, logDir);
+                                }
+
+                                Unsafe.getUnsafe().putObject(w1, Unsafe.getUnsafe().objectFieldOffset(f), value);
                             }
                         } catch (Exception e) {
                             throw new LogError("Unknown property: " + n, e);

core/src/main/resources/log-stdout.conf → core/src/main/resources/io/questdb/site/conf/log.conf

@@ -27,4 +27,4 @@ w.stdout.level=INFO
 # for frequent monitoring
 w.http.min.class=io.questdb.log.LogConsoleWriter
 w.http.min.level=ERROR
-w.http.min.scope=http-min-server
\ No newline at end of file
+w.http.min.scope=http-min-server

core/src/test/java/io/questdb/ServerMainTest.java

+/*******************************************************************************
+ *     ___                  _   ____  ____
+ *    / _ \ _   _  ___  ___| |_|  _ \| __ )
+ *   | | | | | | |/ _ \/ __| __| | | |  _ \
+ *   | |_| | |_| |  __/\__ \ |_| |_| | |_) |
+ *    \__\_\\__,_|\___||___/\__|____/|____/
+ *
+ *  Copyright (c) 2014-2019 Appsicle
+ *  Copyright (c) 2019-2022 QuestDB
+ *
+ *  Licensed under the Apache License, Version 2.0 (the "License");
+ *  you may not use this file except in compliance with the License.
+ *  You may obtain a copy of the License at
+ *
+ *  http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *  Unless required by applicable law or agreed to in writing, software
+ *  distributed under the License is distributed on an "AS IS" BASIS,
+ *  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *  See the License for the specific language governing permissions and
+ *  limitations under the License.
+ *
+ ******************************************************************************/
+
+package io.questdb;
+
+import io.questdb.log.Log;
+import io.questdb.log.LogFactory;
+import org.hamcrest.MatcherAssert;
+
+import static org.hamcrest.CoreMatchers.*;
+
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.rules.TemporaryFolder;
+
+import java.io.File;
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.net.URL;
+import java.nio.file.Paths;
+import java.util.zip.ZipEntry;
+import java.util.zip.ZipOutputStream;
+
+
+public class ServerMainTest {
+
+    @Rule
+    public final TemporaryFolder temp = new TemporaryFolder();
+
+    boolean publicZipStubCreated = false;
+
+    @Before
+    public void setUp() throws IOException {
+        //fake public.zip if it's missing to avoid forcing use of build-web-console profile just to run tests 
+        URL resource = ServerMain.class.getResource("/io/questdb/site/public.zip");
+        if (resource == null) {
+            File siteDir = new File(ServerMain.class.getResource("/io/questdb/site/").getFile());
+            File publicZip = new File(siteDir, "public.zip");
+
+            try (ZipOutputStream zip = new ZipOutputStream(new FileOutputStream(publicZip))) {
+                ZipEntry entry = new ZipEntry("test.txt");
+                zip.putNextEntry(entry);
+                zip.write("test".getBytes());
+                zip.closeEntry();
+            }
+
+            publicZipStubCreated = true;
+        }
+    }
+
+    @After
+    public void tearDown() {
+        if (publicZipStubCreated) {
+            File siteDir = new File(ServerMain.class.getResource("/io/questdb/site/").getFile());
+            File publicZip = new File(siteDir, "public.zip");
+
+            if (publicZip.exists()) {
+                publicZip.delete();
+            }
+        }
+    }
+
+    @Test
+    public void testExtractSiteExtractsDefaultLogConfFileIfItsMissing() throws IOException {
+        Log log = LogFactory.getLog("server-main");
+        File logConf = Paths.get(temp.getRoot().getPath(), "conf", LogFactory.DEFAULT_CONFIG_NAME).toFile();
+
+        MatcherAssert.assertThat(logConf.exists(), is(false));
+
+        ServerMain.extractSite(BuildInformationHolder.INSTANCE, temp.getRoot().getPath(), log);
+
+        MatcherAssert.assertThat(logConf.exists(), is(true));
+    }
+
+    @Test
+    public void testExtractSiteExtractsDefaultConfDirIfItsMissing() throws IOException {
+        Log log = LogFactory.getLog("server-main");
+
+        File conf = Paths.get(temp.getRoot().getPath(), "conf").toFile();
+        File logConf = Paths.get(conf.getPath(), LogFactory.DEFAULT_CONFIG_NAME).toFile();
+        File serverConf = Paths.get(conf.getPath(), "server.conf").toFile();
+        File mimeTypes = Paths.get(conf.getPath(), "mime.types").toFile();
+        //File dateFormats = Paths.get(conf.getPath(), "date.formats").toFile();
+
+        ServerMain.extractSite(BuildInformationHolder.INSTANCE, temp.getRoot().getPath(), log);
+
+        assertExists(logConf);
+        assertExists(serverConf);
+        assertExists(mimeTypes);
+        //assertExists(dateFormats); date.formats is referenced in method but doesn't exist in SCM/jar
+    }
+
+    private static void assertExists(File f) {
+        MatcherAssert.assertThat(f.getPath(), f.exists(), is(true));
+    }
+}

core/src/test/java/io/questdb/log/LogFactoryTest.java

@@ -31,12 +31,17 @@ import io.questdb.std.datetime.microtime.TimestampFormatUtils;
 import io.questdb.std.str.Path;
 import io.questdb.std.str.StringSink;
 import io.questdb.test.tools.TestUtils;
+import org.hamcrest.MatcherAssert;
 import org.junit.Assert;
 import org.junit.Rule;
 import org.junit.Test;
 import org.junit.rules.TemporaryFolder;
 
-import java.io.File;
+import static org.hamcrest.CoreMatchers.*;
+
+import java.io.*;
+import java.nio.file.Paths;
+import java.util.Properties;
 import java.util.concurrent.atomic.AtomicBoolean;
 
 public class LogFactoryTest {
@@ -49,7 +54,7 @@ public class LogFactoryTest {
         System.setProperty(LogFactory.CONFIG_SYSTEM_PROPERTY, "/test-log-bad-writer.conf");
         try (LogFactory factory = new LogFactory()) {
             try {
-                LogFactory.configureFromSystemProperties(factory, null);
+                LogFactory.configureFromSystemProperties(factory, null, null);
                 Assert.fail();
             } catch (LogError e) {
                 Assert.assertEquals("Class not found com.questdb.log.StdOutWriter2", e.getMessage());
@@ -608,6 +613,43 @@ public class LogFactoryTest {
         }
     }
 
+    @Test //also tests ${log.di} resolution
+    public void testWhenCustomLogLocationIsNotSpecifiedThenDefaultLogFileIsUsed() throws Exception {
+        System.clearProperty(LogFactory.CONFIG_SYSTEM_PROPERTY);
+
+        testCustomLogIsCreated(true);
+    }
+
+    @Test
+    public void testWhenCustomLogLocationIsSpecifiedThenDefaultLogFileIsNotUsed() throws IOException {
+        System.setProperty(LogFactory.CONFIG_SYSTEM_PROPERTY, "test-log.conf");
+
+        testCustomLogIsCreated(false);
+    }
+
+    private void testCustomLogIsCreated(boolean isCreated) throws IOException {
+        try (LogFactory factory = new LogFactory()) {
+            File logConfDir = Paths.get(temp.getRoot().getPath(), "conf").toFile();
+            Assert.assertTrue(logConfDir.mkdir());
+
+            File logConfFile = Paths.get(logConfDir.getPath(), LogFactory.DEFAULT_CONFIG_NAME).toFile();
+
+            Properties props = new Properties();
+            props.put("writers", "log_test");
+            props.put("w.log_test.class", "io.questdb.log.LogFileWriter");
+            props.put("w.log_test.location", "${log.dir}\\test.log");
+            props.put("w.log_test.level", "INFO,ERROR");
+            try (FileOutputStream stream = new FileOutputStream(logConfFile)) {
+                props.store(stream, "");
+            }
+
+            LogFactory.configureFromSystemProperties(factory, null, temp.getRoot().getPath());
+
+            File logFile = Paths.get(temp.getRoot().getPath(), "log\\test.log").toFile();
+            MatcherAssert.assertThat(logFile.getAbsolutePath(), logFile.exists(), is(isCreated));
+        }
+    }
+
     private static void assertEnabled(LogRecord r) {
         Assert.assertTrue(r.isEnabled());
         r.$();

pkg/ami/marketplace/assets/systemd.service

@@ -17,7 +17,7 @@ ExecStart=/usr/bin/java \
     -ea -Dnoebug \
     -XX:+UnlockExperimentalVMOptions \
     -XX:+AlwaysPreTouch \
-    -XX:+UseParallelOldGC \
+    -XX:+UseParallelGC \
     -d /var/lib/questdb
 ExecReload=/bin/kill -s HUP $MAINPID
 # Prevent writes to /usr, /boot, and /etc

win64svc/src/questdb.c

@@ -82,7 +82,7 @@ void buildJavaArgs(CONFIG *config) {
     // put together static java opts
     LPCSTR javaOpts = "-XX:+UnlockExperimentalVMOptions"
                       " -XX:+AlwaysPreTouch"
-                      " -XX:+UseParallelOldGC"
+                      " -XX:+UseParallelGC"
                       " ";
 
     // put together classpath

win64svc/src/service.c

 #include <windows.h>
 #include "common.h"
+#include "io.h"
+#include <time.h>
 
 #pragma comment(lib, "advapi32.lib")
 
@@ -52,6 +54,30 @@ void qdbDispatchService(CONFIG *config) {
     }
 }
 
+HANDLE openLogFile(CONFIG *config) {
+    // create log dir
+    char log[MAX_PATH];
+    strcpy(log, config->dir);
+    strcat(log, "\\log");
+
+    if (!makeDir(log)) {
+        return NULL;
+    }
+
+    time_t now = time(NULL);
+    struct tm *t = localtime(&now);
+    strcat(log, "\\service-");
+    strftime(log + strlen(log), MAX_PATH - strlen(log) - 4, "%Y-%m-%dT%H-%M-%S", t);
+    strcat(log, ".txt");
+
+    FILE *stream;
+    if ((stream = fopen(log, "w")) == NULL) {
+        return INVALID_HANDLE_VALUE;
+    }
+
+    return (HANDLE)_get_osfhandle(fileno(stream));
+}
+
 VOID WINAPI qdbService(DWORD argc, LPSTR *argv) {
 
     // Get service name from first command line arg
@@ -105,42 +131,66 @@ VOID WINAPI qdbService(DWORD argc, LPSTR *argv) {
         return;
     }
 
-    STARTUPINFO si;
+    HANDLE log = openLogFile(gConfig);
+    if (log == INVALID_HANDLE_VALUE) {
+        log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Could not open service log file.");
+        return;
+    }
+
     PROCESS_INFORMATION pi;
+    ZeroMemory(&pi, sizeof(pi));
+
+    STARTUPINFO si;
     ZeroMemory(&si, sizeof(si));
     si.cb = sizeof(si);
-    ZeroMemory(&pi, sizeof(pi));
+    si.hStdError = log;
+    si.hStdOutput = log;
+    si.dwFlags |= STARTF_USESTDHANDLES;
 
     char buf[2048];
     sprintf(buf, "Starting %s %s", gConfig->javaExec, gConfig->javaArgs);
     log_event(EVENTLOG_INFORMATION_TYPE, gConfig->serviceName, buf);
 
-    if (!CreateProcess(gConfig->javaExec, gConfig->javaArgs, NULL, NULL, FALSE, 0, NULL, NULL, &si, &pi)) {
+    if (!CreateProcess(gConfig->javaExec, gConfig->javaArgs, NULL, NULL, TRUE/*handles are inherited to redirect stdout/err*/, 0, NULL, NULL, &si, &pi)) {
         log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Could not start java");
         ReportSvcStatus(SERVICE_STOPPED, NO_ERROR, 0);
         return;
     }
 
-//    char buf[2048];
     sprintf(buf, "Started %s %s", gConfig->javaExec, gConfig->javaArgs);
     log_event(EVENTLOG_INFORMATION_TYPE, gConfig->serviceName, buf);
 
-
     // Report running status when initialization is complete.
-
     ReportSvcStatus(SERVICE_RUNNING, NO_ERROR, 0);
 
-    WaitForSingleObject(ghSvcStopEvent, INFINITE);
+    HANDLE lpHandles[2] = { ghSvcStopEvent, pi.hProcess };
+    DWORD dwEvent = WaitForMultipleObjects(2, lpHandles, FALSE /* return if state of any object is signalled*/, INFINITE );
 
-    if (!TerminateProcess(pi.hProcess, 0)) {
-        log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Failed to terminate java process");
-    }
+    switch (dwEvent) {
+        // service stop event was signaled
+        case WAIT_FAILED:
+        case WAIT_TIMEOUT:
+        case WAIT_OBJECT_0 + 0:
+            if (WAIT_FAILED == dwEvent) {
+                log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Java process or service wait failed.");
+            }
+
+            if (!TerminateProcess(pi.hProcess, 0)) {
+                log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Failed to terminate java process");
+            }
 
-    log_event(EVENTLOG_INFORMATION_TYPE, gConfig->serviceName, "Shutdown Java process");
+            log_event(EVENTLOG_INFORMATION_TYPE, gConfig->serviceName, "Shutdown Java process");
+            break;
+        // java process exit was signalled
+        case WAIT_OBJECT_0 + 1:
+            log_event(EVENTLOG_ERROR_TYPE, gConfig->serviceName, "Java process was abnormally terminated.");
+            break;
+    }
 
     // Close process and thread handles.
     CloseHandle(pi.hProcess);
     CloseHandle(pi.hThread);
+    CloseHandle(log);
 
     ReportSvcStatus(SERVICE_STOPPED, NO_ERROR, 0);