X-Git-Url: http://git.argeo.org/?a=blobdiff_plain;f=org.argeo.init%2Fsrc%2Forg%2Fargeo%2Finit%2Flogging%2FThinLogging.java;h=c2ce215288171bf94543a5fd0a949013b25b6bf2;hb=c692c089327ab02a19dc5dae90bb003cdf75956d;hp=9866a1f232e2a218d9c98d8699b089f619ca7d01;hpb=1010bff4f1ffadbf3f7988fbd3eba70f5d672c88;p=lgpl%2Fargeo-commons.git diff --git a/org.argeo.init/src/org/argeo/init/logging/ThinLogging.java b/org.argeo.init/src/org/argeo/init/logging/ThinLogging.java index 9866a1f23..c2ce21528 100644 --- a/org.argeo.init/src/org/argeo/init/logging/ThinLogging.java +++ b/org.argeo.init/src/org/argeo/init/logging/ThinLogging.java @@ -16,16 +16,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.init.RuntimeContext; +import org.argeo.init.Service; + /** * 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 +37,24 @@ class ThinLogging implements Consumer> { 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 jounrald compatible output, either: auto (default), true, + * or false. + */ + final static String PROP_ARGEO_LOGGING_JOURNALD = "argeo.logging.journald"; + /** + * 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 +65,38 @@ class ThinLogging implements Consumer> { private NavigableMap levels = new TreeMap<>(); private volatile boolean updatingConfiguration = false; - private final ExecutorService executor; private final LogEntryPublisher publisher; + private PrintStreamSubscriber synchronousSubscriber; 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); + } 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 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 +119,46 @@ class ThinLogging implements Consumer> { 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 = Service.getRuntimeContext(); + 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 + } } } private Level computeApplicableLevel(String name) { Map.Entry 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 +211,6 @@ class ThinLogging implements Consumer> { updatingConfiguration = false; levels.notifyAll(); } - } Flow.Publisher> getLogEntryPublisher() { @@ -213,10 +221,49 @@ class ThinLogging implements Consumer> { 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 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 +308,7 @@ class ThinLogging implements Consumer> { // 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 +321,22 @@ class ThinLogging implements Consumer> { // 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 +346,7 @@ class ThinLogging implements Consumer> { 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 +355,18 @@ class ThinLogging implements Consumer> { 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.eclipse.osgi.internal.log.LoggerImpl": + case "org.argeo.api.cms.CmsLog": + case "org.argeo.init.osgi.OsgiBootUtils": case "org.slf4j.impl.ArgeoLogger": + case "org.argeo.cms.internal.osgi.CmsOsgiLogger": case "org.eclipse.jetty.util.log.Slf4jLog": + case "sun.util.logging.internal.LoggingProviderImpl$JULWrapper": lowestLoggerInterface = i; continue stack; default: @@ -323,38 +390,14 @@ class ThinLogging implements Consumer> { private class LogEntryPublisher extends SubmissionPublisher> { - 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 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 +443,8 @@ class ThinLogging implements Consumer> { private PrintStream err; private int writeToErrLevel = Level.WARNING.getSeverity(); + private Subscription subscription; + protected PrintStreamSubscriber() { this(System.out, System.err); } @@ -415,7 +460,8 @@ class ThinLogging implements Consumer> { @Override public void onSubscribe(Subscription subscription) { - subscription.request(Long.MAX_VALUE); + this.subscription = subscription; + this.subscription.request(1); } @Override @@ -426,6 +472,8 @@ class ThinLogging implements Consumer> { out.print(toPrint(item)); } // TODO flush for journald? + if (this.subscription != null) + this.subscription.request(1); } @Override @@ -487,10 +535,9 @@ class ThinLogging implements Consumer> { protected String toPrint(Map 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,12 +566,13 @@ class ThinLogging implements Consumer> { 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()); } } @@ -538,6 +586,16 @@ class ThinLogging implements Consumer> { 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 ait 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 + } + } }