Clean up Argeo Init
[lgpl/argeo-commons.git] / org.argeo.init / src / org / argeo / init / logging / ThinLogging.java
index 9866a1f232e2a218d9c98d8699b089f619ca7d01..2b2f6b3a74f3b6294aaf109ed299f22a370720a3 100644 (file)
@@ -1,9 +1,14 @@
 package org.argeo.init.logging;
 
+import java.io.IOException;
 import java.io.PrintStream;
 import java.io.Serializable;
 import java.lang.System.Logger;
 import java.lang.System.Logger.Level;
+import java.nio.charset.StandardCharsets;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.nio.file.Paths;
 import java.text.MessageFormat;
 import java.time.Instant;
 import java.util.Collections;
@@ -16,16 +21,17 @@ import java.util.ResourceBundle;
 import java.util.SortedMap;
 import java.util.StringTokenizer;
 import java.util.TreeMap;
-import java.util.concurrent.Executor;
-import java.util.concurrent.ExecutorService;
-import java.util.concurrent.Executors;
 import java.util.concurrent.Flow;
 import java.util.concurrent.Flow.Subscription;
+import java.util.concurrent.ForkJoinPool;
 import java.util.concurrent.SubmissionPublisher;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.function.Consumer;
 
+import org.argeo.api.init.RuntimeContext;
+import org.argeo.internal.init.InternalState;
+
 /**
  * A thin logging system based on the {@link Logger} framework. It is a
  * {@link Consumer} of configuration, and can be registered as such.
@@ -36,8 +42,26 @@ class ThinLogging implements Consumer<Map<String, Object>> {
        final static String DEFAULT_LEVEL_PROPERTY = "log";
        final static String LEVEL_PROPERTY_PREFIX = DEFAULT_LEVEL_PROPERTY + ".";
 
-       final static String JOURNALD_PROPERTY = "argeo.logging.journald";
-       final static String CALL_LOCATION_PROPERTY = "argeo.logging.callLocation";
+       /**
+        * Whether logged event are only immediately printed to the standard output.
+        * Required for native images.
+        */
+       final static String PROP_ARGEO_LOGGING_SYNCHRONOUS = "argeo.logging.synchronous";
+       /**
+        * Whether to enable journald compatible output, either: auto (default), true,
+        * or false.
+        */
+       final static String PROP_ARGEO_LOGGING_JOURNALD = "argeo.logging.journald";
+       /** A file to which additionally write log entries. */
+       final static String PROP_ARGEO_LOGGING_FILE = "argeo.logging.file";
+       /**
+        * The level from which call location (that is, line number in Java code) will
+        * be searched (default is WARNING)
+        */
+       final static String PROP_ARGEO_LOGGING_CALL_LOCATION_LEVEL = "argeo.logging.callLocationLevel";
+
+       final static String ENV_INVOCATION_ID = "INVOCATION_ID";
+       final static String ENV_GIO_LAUNCHED_DESKTOP_FILE_PID = "GIO_LAUNCHED_DESKTOP_FILE_PID";
 
        private final static AtomicLong nextEntry = new AtomicLong(0l);
 
@@ -48,43 +72,54 @@ class ThinLogging implements Consumer<Map<String, Object>> {
        private NavigableMap<String, Level> levels = new TreeMap<>();
        private volatile boolean updatingConfiguration = false;
 
-       private final ExecutorService executor;
        private final LogEntryPublisher publisher;
+       private PrintStreamSubscriber synchronousSubscriber;
+       private PrintStream fileOut;
 
        private final boolean journald;
        private final Level callLocationLevel;
 
-       ThinLogging() {
-               executor = Executors.newCachedThreadPool((r) -> {
-                       Thread t = new Thread(r);
-                       t.setDaemon(true);
-                       return t;
-               });
-               publisher = new LogEntryPublisher(executor, Flow.defaultBufferSize());
-
-               PrintStreamSubscriber subscriber = new PrintStreamSubscriber();
-               publisher.subscribe(subscriber);
+       private final boolean synchronous;
 
+       ThinLogging() {
+               synchronous = Boolean.parseBoolean(System.getProperty(PROP_ARGEO_LOGGING_SYNCHRONOUS, "false"));
+               if (synchronous) {
+                       synchronousSubscriber = new PrintStreamSubscriber();
+                       publisher = null;
+               } else {
+                       PrintStreamSubscriber subscriber = new PrintStreamSubscriber();
+                       publisher = new LogEntryPublisher();
+                       publisher.subscribe(subscriber);
+                       String logFileStr = System.getProperty(PROP_ARGEO_LOGGING_FILE);
+                       if (logFileStr != null) {
+                               Path logFilePath = Paths.get(logFileStr);
+                               if (!Files.exists(logFilePath.getParent())) {
+                                       System.err.println("Parent directory of " + logFilePath + " does not exist");
+                               } else {
+                                       try {
+                                               fileOut = new PrintStream(Files.newOutputStream(logFilePath), true, StandardCharsets.UTF_8);
+                                               publisher.subscribe(new PrintStreamSubscriber(fileOut, fileOut));
+                                       } catch (IOException e) {
+                                               System.err.println("Cannot write log to " + logFilePath);
+                                               e.printStackTrace();
+                                       }
+                               }
+                       }
+               }
                Runtime.getRuntime().addShutdownHook(new Thread(() -> close(), "Log shutdown"));
 
                // initial default level
-               levels.put("", Level.WARNING);
+               levels.put(DEFAULT_LEVEL_NAME, Level.WARNING);
 
                // Logging system config
                // journald
-
-//             Map<String, String> env = new TreeMap<>(System.getenv());
-//             for (String key : env.keySet()) {
-//                     System.out.println(key + "=" + env.get(key));
-//             }
-
-               String journaldStr = System.getProperty(JOURNALD_PROPERTY, "auto");
+               String journaldStr = System.getProperty(PROP_ARGEO_LOGGING_JOURNALD, "auto");
                switch (journaldStr) {
                case "auto":
-                       String systemdInvocationId = System.getenv("INVOCATION_ID");
+                       String systemdInvocationId = System.getenv(ENV_INVOCATION_ID);
                        if (systemdInvocationId != null) {// in systemd
-                               // check whether we are indirectly in a desktop app (e.g. eclipse)
-                               String desktopFilePid = System.getenv("GIO_LAUNCHED_DESKTOP_FILE_PID");
+                               // check whether we are indirectly in a desktop app (typically an IDE)
+                               String desktopFilePid = System.getenv(ENV_GIO_LAUNCHED_DESKTOP_FILE_PID);
                                if (desktopFilePid != null) {
                                        Long javaPid = ProcessHandle.current().pid();
                                        if (!javaPid.toString().equals(desktopFilePid)) {
@@ -107,49 +142,54 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                        break;
                default:
                        throw new IllegalArgumentException(
-                                       "Unsupported value '" + journaldStr + "' for property " + JOURNALD_PROPERTY);
+                                       "Unsupported value '" + journaldStr + "' for property " + PROP_ARGEO_LOGGING_JOURNALD);
                }
 
-               String callLocationStr = System.getProperty(CALL_LOCATION_PROPERTY, Level.WARNING.getName());
+               String callLocationStr = System.getProperty(PROP_ARGEO_LOGGING_CALL_LOCATION_LEVEL, Level.WARNING.getName());
                callLocationLevel = Level.valueOf(callLocationStr);
        }
 
        private void close() {
-               publisher.close();
-               try {
-                       // we ait a bit in order to make sure all messages are flushed
-                       // TODO synchronize more efficiently
-                       executor.awaitTermination(300, TimeUnit.MILLISECONDS);
-               } catch (InterruptedException e) {
-                       // silent
+               RuntimeContext runtimeContext = InternalState.getMainRuntimeContext();
+               if (runtimeContext != null) {
+                       try {
+                               runtimeContext.waitForStop(0);
+                       } catch (InterruptedException e) {
+                               // silent
+                       }
+               }
+
+               if (!synchronous) {
+                       publisher.close();
+                       try {
+                               // we wait a bit in order to make sure all messages are flushed
+                               // TODO synchronize more efficiently
+                               // executor.awaitTermination(300, TimeUnit.MILLISECONDS);
+                               ForkJoinPool.commonPool().awaitTermination(300, TimeUnit.MILLISECONDS);
+                       } catch (InterruptedException e) {
+                               // silent
+                       }
+               }
+
+               if (fileOut != null) {
+                       try {
+                               fileOut.close();
+                       } catch (Exception e) {
+                               // silent
+                       }
                }
        }
 
        private Level computeApplicableLevel(String name) {
                Map.Entry<String, Level> entry = levels.floorEntry(name);
                assert entry != null;
-               return entry.getValue();
+               if (name.startsWith(entry.getKey()))
+                       return entry.getValue();
+               else
+                       return levels.get(DEFAULT_LEVEL_NAME);// default
 
        }
 
-//     private boolean isLoggable(String name, Level level) {
-//             Objects.requireNonNull(name);
-//             Objects.requireNonNull(level);
-//
-//             if (updatingConfiguration) {
-//                     synchronized (levels) {
-//                             try {
-//                                     levels.wait();
-//                                     // TODO make exit more robust
-//                             } catch (InterruptedException e) {
-//                                     throw new IllegalStateException(e);
-//                             }
-//                     }
-//             }
-//
-//             return level.getSeverity() >= computeApplicableLevel(name).getSeverity();
-//     }
-
        public Logger getLogger(String name, Module module) {
                if (!loggers.containsKey(name)) {
                        ThinLogger logger = new ThinLogger(name, computeApplicableLevel(name));
@@ -202,7 +242,6 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                        updatingConfiguration = false;
                        levels.notifyAll();
                }
-
        }
 
        Flow.Publisher<Map<String, Serializable>> getLogEntryPublisher() {
@@ -213,10 +252,49 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                return Collections.unmodifiableNavigableMap(levels);
        }
 
+       private void dispatchLogEntry(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
+                       Thread thread, Throwable thrown, StackTraceElement callLocation) {
+               assert level != null;
+               assert logger != null;
+//             assert msg != null;
+               assert instant != null;
+               assert thread != null;
+
+               if (msg == null)
+                       msg = "null";
+
+               final long sequence = nextEntry.incrementAndGet();
+
+               Map<String, Serializable> logEntry = new LogEntryMap(sequence);
+
+               // same object as key class name
+               logEntry.put(KEY_LEVEL, level);
+               logEntry.put(KEY_MSG, msg);
+               logEntry.put(KEY_INSTANT, instant);
+               if (thrown != null)
+                       logEntry.put(KEY_THROWABLE, thrown);
+               if (callLocation != null)
+                       logEntry.put(KEY_CALL_LOCATION, callLocation);
+
+               // object is a string
+               logEntry.put(KEY_LOGGER, logger.getName());
+               logEntry.put(KEY_THREAD, thread.getName());
+
+               // should be unmodifiable for security reasons
+               if (synchronous) {
+                       assert synchronousSubscriber != null;
+                       synchronousSubscriber.onNext(logEntry);
+               } else {
+                       if (!publisher.isClosed())
+                               publisher.submit(Collections.unmodifiableMap(logEntry));
+               }
+
+       }
+
        /*
         * INTERNAL CLASSES
         */
-       
+
        private class ThinLogger implements System.Logger {
                private final String name;
 
@@ -261,7 +339,7 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                        // measure timestamp first
                        Instant now = Instant.now();
                        Thread thread = Thread.currentThread();
-                       publisher.log(this, level, bundle, msg, now, thread, thrown, findCallLocation(level, thread));
+                       dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, thrown, findCallLocation(level, thread));
                }
 
                @Override
@@ -274,8 +352,22 @@ class ThinLogging implements Consumer<Map<String, Object>> {
 
                        // NOTE: this is the method called when logging a plain message without
                        // exception, so it should be considered as a format only when args are not null
+//                     if (format.contains("{}"))// workaround for weird Jetty formatting
+//                             params = null;
+                       // TODO move this to slf4j wrapper?
+                       if (format.contains("{}")) {
+                               StringBuilder sb = new StringBuilder();
+                               String[] segments = format.split("\\{\\}");
+                               for (int i = 0; i < segments.length; i++) {
+                                       sb.append(segments[i]);
+                                       if (i != (segments.length - 1))
+                                               sb.append("{" + i + "}");
+                               }
+                               format = sb.toString();
+                       }
                        String msg = params == null ? format : MessageFormat.format(format, params);
-                       publisher.log(this, level, bundle, msg, now, thread, (Throwable) null, findCallLocation(level, thread));
+                       dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, (Throwable) null,
+                                       findCallLocation(level, thread));
                }
 
                private void setLevel(Level level) {
@@ -285,6 +377,7 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                private StackTraceElement findCallLocation(Level level, Thread thread) {
                        assert level != null;
                        assert thread != null;
+                       // TODO rather use a StackWalker and make it smarter
                        StackTraceElement callLocation = null;
                        if (level.getSeverity() >= callLocationLevel.getSeverity()) {
                                StackTraceElement[] stack = thread.getStackTrace();
@@ -293,13 +386,18 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                                        String className = stack[i].getClassName();
                                        switch (className) {
                                        // TODO make it more configurable
+                                       // FIXME deal with privileges stacks (in Equinox)
                                        case "java.lang.System$Logger":
                                        case "java.util.logging.Logger":
                                        case "org.apache.commons.logging.Log":
                                        case "org.osgi.service.log.Logger":
-                                       case "org.argeo.cms.Log":
-                                       case "org.slf4j.impl.ArgeoLogger":
+                                       case "org.eclipse.osgi.internal.log.LoggerImpl":
+                                       case "org.argeo.api.cms.CmsLog":
                                        case "org.eclipse.jetty.util.log.Slf4jLog":
+                                       case "sun.util.logging.internal.LoggingProviderImpl$JULWrapper":
+                                       case "org.slf4j.impl.ArgeoLogger":
+                                       case "org.argeo.cms.internal.osgi.CmsOsgiLogger":
+                                       case "org.argeo.init.osgi.OsgiBootUtils":
                                                lowestLoggerInterface = i;
                                                continue stack;
                                        default:
@@ -323,38 +421,14 @@ class ThinLogging implements Consumer<Map<String, Object>> {
 
        private class LogEntryPublisher extends SubmissionPublisher<Map<String, Serializable>> {
 
-               private LogEntryPublisher(Executor executor, int maxBufferCapacity) {
-                       super(executor, maxBufferCapacity);
+               private LogEntryPublisher() {
+                       super();
                }
 
-               private void log(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
-                               Thread thread, Throwable thrown, StackTraceElement callLocation) {
-                       assert level != null;
-                       assert logger != null;
-                       assert msg != null;
-                       assert instant != null;
-                       assert thread != null;
-
-                       final long sequence = nextEntry.incrementAndGet();
-
-                       Map<String, Serializable> logEntry = new LogEntryMap(sequence);
-
-                       // same object as key class name
-                       logEntry.put(KEY_LEVEL, level);
-                       logEntry.put(KEY_MSG, msg);
-                       logEntry.put(KEY_INSTANT, instant);
-                       if (thrown != null)
-                               logEntry.put(KEY_THROWABLE, thrown);
-                       if (callLocation != null)
-                               logEntry.put(KEY_CALL_LOCATION, callLocation);
-
-                       // object is a string
-                       logEntry.put(KEY_LOGGER, logger.getName());
-                       logEntry.put(KEY_THREAD, thread.getName());
-
-                       // should be unmodifiable for security reasons
-                       submit(Collections.unmodifiableMap(logEntry));
-               }
+//             private void log(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
+//                             Thread thread, Throwable thrown, StackTraceElement callLocation) {
+//
+//             }
 
        }
 
@@ -400,6 +474,8 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                private PrintStream err;
                private int writeToErrLevel = Level.WARNING.getSeverity();
 
+               private Subscription subscription;
+
                protected PrintStreamSubscriber() {
                        this(System.out, System.err);
                }
@@ -415,7 +491,8 @@ class ThinLogging implements Consumer<Map<String, Object>> {
 
                @Override
                public void onSubscribe(Subscription subscription) {
-                       subscription.request(Long.MAX_VALUE);
+                       this.subscription = subscription;
+                       this.subscription.request(1);
                }
 
                @Override
@@ -426,6 +503,8 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                                out.print(toPrint(item));
                        }
                        // TODO flush for journald?
+                       if (this.subscription != null)
+                               this.subscription.request(1);
                }
 
                @Override
@@ -487,10 +566,9 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                protected String toPrint(Map<String, Serializable> logEntry) {
                        StringBuilder sb = new StringBuilder();
                        StringTokenizer st = new StringTokenizer((String) logEntry.get(KEY_MSG), "\r\n");
-                       assert st.hasMoreTokens();
 
                        // first line
-                       String firstLine = st.nextToken();
+                       String firstLine = st.hasMoreTokens() ? st.nextToken() : "";
                        sb.append(firstLinePrefix(logEntry));
                        sb.append(firstLine);
                        sb.append(firstLineSuffix(logEntry));
@@ -519,25 +597,36 @@ class ThinLogging implements Consumer<Map<String, Object>> {
                        sb.append('\n');
                        for (StackTraceElement ste : throwable.getStackTrace()) {
                                sb.append(prefix);
+                               sb.append('\t');
                                sb.append(ste.toString());
                                sb.append('\n');
                        }
                        if (throwable.getCause() != null) {
                                sb.append(prefix);
-                               sb.append("caused by ");
+                               sb.append("Caused by: ");
                                addThrowable(sb, prefix, throwable.getCause());
                        }
                }
        }
 
-       public static void main(String args[]) {
-               Logger logger = System.getLogger(ThinLogging.class.getName());
-               logger.log(Logger.Level.ALL, "Log all");
-               logger.log(Logger.Level.TRACE, "Multi\nline\ntrace");
-               logger.log(Logger.Level.DEBUG, "Log debug");
-               logger.log(Logger.Level.INFO, "Log info");
-               logger.log(Logger.Level.WARNING, "Log warning");
-               logger.log(Logger.Level.ERROR, "Log exception", new Throwable());
-       }
+//     public static void main(String args[]) {
+//             Logger logger = System.getLogger(ThinLogging.class.getName());
+//             logger.log(Logger.Level.ALL, "Log all");
+//             logger.log(Logger.Level.TRACE, "Multi\nline\ntrace");
+//             logger.log(Logger.Level.DEBUG, "Log debug");
+//             logger.log(Logger.Level.INFO, "Log info");
+//             logger.log(Logger.Level.WARNING, "Log warning");
+//             logger.log(Logger.Level.ERROR, "Log exception", new Throwable());
+//
+//             try {
+//                     // we wait a bit in order to make sure all messages are flushed
+//                     // TODO synchronize more efficiently
+//                     // executor.awaitTermination(300, TimeUnit.MILLISECONDS);
+//                     ForkJoinPool.commonPool().awaitTermination(300, TimeUnit.MILLISECONDS);
+//             } catch (InterruptedException e) {
+//                     // silent
+//             }
+//
+//     }
 
 }