]> git.argeo.org Git - lgpl/argeo-commons.git/blob - org.argeo.init/src/org/argeo/init/logging/ThinLogging.java
Clarify ACR API
[lgpl/argeo-commons.git] / org.argeo.init / src / org / argeo / init / logging / ThinLogging.java
1 package org.argeo.init.logging;
2
3 import java.io.IOException;
4 import java.io.PrintStream;
5 import java.io.Serializable;
6 import java.lang.System.Logger;
7 import java.lang.System.Logger.Level;
8 import java.nio.charset.StandardCharsets;
9 import java.nio.file.Files;
10 import java.nio.file.Path;
11 import java.nio.file.Paths;
12 import java.text.MessageFormat;
13 import java.time.Instant;
14 import java.util.Collections;
15 import java.util.HashMap;
16 import java.util.Iterator;
17 import java.util.Map;
18 import java.util.NavigableMap;
19 import java.util.Objects;
20 import java.util.ResourceBundle;
21 import java.util.SortedMap;
22 import java.util.StringTokenizer;
23 import java.util.TreeMap;
24 import java.util.concurrent.Flow;
25 import java.util.concurrent.Flow.Subscription;
26 import java.util.concurrent.ForkJoinPool;
27 import java.util.concurrent.SubmissionPublisher;
28 import java.util.concurrent.TimeUnit;
29 import java.util.concurrent.atomic.AtomicLong;
30 import java.util.function.Consumer;
31
32 import org.argeo.api.init.RuntimeContext;
33 import org.argeo.internal.init.InternalState;
34
35 /**
36 * A thin logging system based on the {@link Logger} framework. It is a
37 * {@link Consumer} of configuration, and can be registered as such.
38 */
39 class ThinLogging implements Consumer<Map<String, Object>> {
40 final static String DEFAULT_LEVEL_NAME = "";
41
42 final static String DEFAULT_LEVEL_PROPERTY = "log";
43 final static String LEVEL_PROPERTY_PREFIX = DEFAULT_LEVEL_PROPERTY + ".";
44
45 /**
46 * Whether logged event are only immediately printed to the standard output.
47 * Required for native images.
48 */
49 final static String PROP_ARGEO_LOGGING_SYNCHRONOUS = "argeo.logging.synchronous";
50 /**
51 * Whether to enable journald compatible output, either: auto (default), true,
52 * or false.
53 */
54 final static String PROP_ARGEO_LOGGING_JOURNALD = "argeo.logging.journald";
55 /** A file to which additionally write log entries. */
56 final static String PROP_ARGEO_LOGGING_FILE = "argeo.logging.file";
57 /**
58 * The level from which call location (that is, line number in Java code) will
59 * be searched (default is WARNING)
60 */
61 final static String PROP_ARGEO_LOGGING_CALL_LOCATION_LEVEL = "argeo.logging.callLocationLevel";
62
63 final static String ENV_INVOCATION_ID = "INVOCATION_ID";
64 final static String ENV_GIO_LAUNCHED_DESKTOP_FILE_PID = "GIO_LAUNCHED_DESKTOP_FILE_PID";
65
66 private final static AtomicLong nextEntry = new AtomicLong(0l);
67
68 // we don't synchronize maps on purpose as it would be
69 // too expensive during normal operation
70 // updates to the config may be shortly inconsistent
71 private SortedMap<String, ThinLogger> loggers = Collections.synchronizedSortedMap(new TreeMap<>());
72 private NavigableMap<String, Level> levels = new TreeMap<>();
73 private volatile boolean updatingConfiguration = false;
74
75 private final LogEntryPublisher publisher;
76 private PrintStreamSubscriber synchronousSubscriber;
77 private PrintStream fileOut;
78
79 private final boolean journald;
80 private final Level callLocationLevel;
81
82 private final boolean synchronous;
83
84 ThinLogging() {
85 synchronous = Boolean.parseBoolean(System.getProperty(PROP_ARGEO_LOGGING_SYNCHRONOUS, "false"));
86 if (synchronous) {
87 synchronousSubscriber = new PrintStreamSubscriber();
88 publisher = null;
89 } else {
90 PrintStreamSubscriber subscriber = new PrintStreamSubscriber();
91 publisher = new LogEntryPublisher();
92 publisher.subscribe(subscriber);
93 String logFileStr = System.getProperty(PROP_ARGEO_LOGGING_FILE);
94 if (logFileStr != null) {
95 Path logFilePath = Paths.get(logFileStr);
96 if (!Files.exists(logFilePath.getParent())) {
97 System.err.println("Parent directory of " + logFilePath + " does not exist");
98 } else {
99 try {
100 fileOut = new PrintStream(Files.newOutputStream(logFilePath), true, StandardCharsets.UTF_8);
101 publisher.subscribe(new PrintStreamSubscriber(fileOut, fileOut));
102 } catch (IOException e) {
103 System.err.println("Cannot write log to " + logFilePath);
104 e.printStackTrace();
105 }
106 }
107 }
108 }
109 Runtime.getRuntime().addShutdownHook(new Thread(() -> close(), "Log shutdown"));
110
111 // initial default level
112 levels.put(DEFAULT_LEVEL_NAME, Level.WARNING);
113
114 // Logging system config
115 // journald
116 String journaldStr = System.getProperty(PROP_ARGEO_LOGGING_JOURNALD, "auto");
117 switch (journaldStr) {
118 case "auto":
119 String systemdInvocationId = System.getenv(ENV_INVOCATION_ID);
120 if (systemdInvocationId != null) {// in systemd
121 // check whether we are indirectly in a desktop app (typically an IDE)
122 String desktopFilePid = System.getenv(ENV_GIO_LAUNCHED_DESKTOP_FILE_PID);
123 if (desktopFilePid != null) {
124 Long javaPid = ProcessHandle.current().pid();
125 if (!javaPid.toString().equals(desktopFilePid)) {
126 journald = false;
127 break;
128 }
129 }
130 journald = true;
131 break;
132 }
133 journald = false;
134 break;
135 case "true":
136 case "on":
137 journald = true;
138 break;
139 case "false":
140 case "off":
141 journald = false;
142 break;
143 default:
144 throw new IllegalArgumentException(
145 "Unsupported value '" + journaldStr + "' for property " + PROP_ARGEO_LOGGING_JOURNALD);
146 }
147
148 String callLocationStr = System.getProperty(PROP_ARGEO_LOGGING_CALL_LOCATION_LEVEL, Level.WARNING.getName());
149 callLocationLevel = Level.valueOf(callLocationStr);
150 }
151
152 private void close() {
153 RuntimeContext runtimeContext = InternalState.getMainRuntimeContext();
154 if (runtimeContext != null) {
155 try {
156 runtimeContext.waitForStop(0);
157 } catch (InterruptedException e) {
158 // silent
159 }
160 }
161
162 if (!synchronous) {
163 publisher.close();
164 try {
165 // we wait a bit in order to make sure all messages are flushed
166 // TODO synchronize more efficiently
167 // executor.awaitTermination(300, TimeUnit.MILLISECONDS);
168 ForkJoinPool.commonPool().awaitTermination(300, TimeUnit.MILLISECONDS);
169 } catch (InterruptedException e) {
170 // silent
171 }
172 }
173
174 if (fileOut != null) {
175 try {
176 fileOut.close();
177 } catch (Exception e) {
178 // silent
179 }
180 }
181 }
182
183 private Level computeApplicableLevel(String name) {
184 Map.Entry<String, Level> entry = levels.floorEntry(name);
185 assert entry != null;
186 if (name.startsWith(entry.getKey()))
187 return entry.getValue();
188 else
189 return levels.get(DEFAULT_LEVEL_NAME);// default
190
191 }
192
193 public Logger getLogger(String name, Module module) {
194 Objects.requireNonNull(name, "logger name");
195 if (!loggers.containsKey(name)) {
196 ThinLogger logger = new ThinLogger(name, computeApplicableLevel(name));
197 loggers.put(name, logger);
198 return logger;
199 }
200 return loggers.get(name);
201 }
202
203 public void accept(Map<String, Object> configuration) {
204 synchronized (levels) {
205 updatingConfiguration = true;
206
207 Map<String, Level> backup = new TreeMap<>(levels);
208
209 boolean fullReset = configuration.containsKey(DEFAULT_LEVEL_PROPERTY);
210 try {
211 properties: for (String property : configuration.keySet()) {
212 if (!property.startsWith(LEVEL_PROPERTY_PREFIX))
213 continue properties;
214 String levelStr = configuration.get(property).toString();
215 Level level = Level.valueOf(levelStr);
216 levels.put(property.substring(LEVEL_PROPERTY_PREFIX.length()), level);
217 }
218
219 if (fullReset) {
220 Iterator<Map.Entry<String, Level>> it = levels.entrySet().iterator();
221 while (it.hasNext()) {
222 Map.Entry<String, Level> entry = it.next();
223 String name = entry.getKey();
224 if (!configuration.containsKey(LEVEL_PROPERTY_PREFIX + name)) {
225 it.remove();
226 }
227 }
228 Level newDefaultLevel = Level.valueOf(configuration.get(DEFAULT_LEVEL_PROPERTY).toString());
229 levels.put(DEFAULT_LEVEL_NAME, newDefaultLevel);
230 // TODO notify everyone?
231 }
232 assert levels.containsKey(DEFAULT_LEVEL_NAME);
233
234 // recompute all levels
235 for (String name : loggers.keySet()) {
236 ThinLogger logger = loggers.get(name);
237 logger.setLevel(computeApplicableLevel(name));
238 }
239 } catch (IllegalArgumentException e) {
240 e.printStackTrace();
241 levels.clear();
242 levels.putAll(backup);
243 }
244 updatingConfiguration = false;
245 levels.notifyAll();
246 }
247 }
248
249 Flow.Publisher<Map<String, Serializable>> getLogEntryPublisher() {
250 return publisher;
251 }
252
253 Map<String, Level> getLevels() {
254 return Collections.unmodifiableNavigableMap(levels);
255 }
256
257 private void dispatchLogEntry(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
258 Thread thread, Throwable thrown, StackTraceElement callLocation) {
259 assert level != null;
260 assert logger != null;
261 // assert msg != null;
262 assert instant != null;
263 assert thread != null;
264
265 if (msg == null)
266 msg = "null";
267
268 final long sequence = nextEntry.incrementAndGet();
269
270 Map<String, Serializable> logEntry = new LogEntryMap(sequence);
271
272 // same object as key class name
273 logEntry.put(KEY_LEVEL, level);
274 logEntry.put(KEY_MSG, msg);
275 logEntry.put(KEY_INSTANT, instant);
276 if (thrown != null)
277 logEntry.put(KEY_THROWABLE, thrown);
278 if (callLocation != null)
279 logEntry.put(KEY_CALL_LOCATION, callLocation);
280
281 // object is a string
282 logEntry.put(KEY_LOGGER, logger.getName());
283 logEntry.put(KEY_THREAD, thread.getName());
284
285 // should be unmodifiable for security reasons
286 if (synchronous) {
287 assert synchronousSubscriber != null;
288 synchronousSubscriber.onNext(logEntry);
289 } else {
290 if (!publisher.isClosed())
291 publisher.submit(Collections.unmodifiableMap(logEntry));
292 }
293
294 }
295
296 /*
297 * INTERNAL CLASSES
298 */
299
300 private class ThinLogger implements System.Logger {
301 private final String name;
302
303 private Level level;
304
305 protected ThinLogger(String name, Level level) {
306 assert Objects.nonNull(name);
307 this.name = name;
308 this.level = level;
309 }
310
311 @Override
312 public String getName() {
313 return name;
314 }
315
316 @Override
317 public boolean isLoggable(Level level) {
318 return level.getSeverity() >= getLevel().getSeverity();
319 // TODO optimise by referencing the applicable level in this class?
320 // return ThinLogging.this.isLoggable(name, level);
321 }
322
323 private Level getLevel() {
324 if (updatingConfiguration) {
325 synchronized (levels) {
326 try {
327 levels.wait();
328 // TODO make exit more robust
329 } catch (InterruptedException e) {
330 throw new IllegalStateException(e);
331 }
332 }
333 }
334 return level;
335 }
336
337 @Override
338 public void log(Level level, ResourceBundle bundle, String msg, Throwable thrown) {
339 if (!isLoggable(level))
340 return;
341 // measure timestamp first
342 Instant now = Instant.now();
343 Thread thread = Thread.currentThread();
344 dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, thrown, findCallLocation(level, thread));
345 }
346
347 @Override
348 public void log(Level level, ResourceBundle bundle, String format, Object... params) {
349 if (!isLoggable(level))
350 return;
351 // measure timestamp first
352 Instant now = Instant.now();
353 Thread thread = Thread.currentThread();
354
355 // NOTE: this is the method called when logging a plain message without
356 // exception, so it should be considered as a format only when args are not null
357 // if (format.contains("{}"))// workaround for weird Jetty formatting
358 // params = null;
359 // TODO move this to slf4j wrapper?
360 if (format.contains("{}")) {
361 StringBuilder sb = new StringBuilder();
362 String[] segments = format.split("\\{\\}");
363 for (int i = 0; i < segments.length; i++) {
364 sb.append(segments[i]);
365 if (i != (segments.length - 1))
366 sb.append("{" + i + "}");
367 }
368 format = sb.toString();
369 }
370 String msg = params == null ? format : MessageFormat.format(format, params);
371 dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, (Throwable) null,
372 findCallLocation(level, thread));
373 }
374
375 private void setLevel(Level level) {
376 this.level = level;
377 }
378
379 private StackTraceElement findCallLocation(Level level, Thread thread) {
380 assert level != null;
381 assert thread != null;
382 // TODO rather use a StackWalker and make it smarter
383 StackTraceElement callLocation = null;
384 if (level.getSeverity() >= callLocationLevel.getSeverity()) {
385 StackTraceElement[] stack = thread.getStackTrace();
386 int lowestLoggerInterface = 0;
387 stack: for (int i = 2; i < stack.length; i++) {
388 String className = stack[i].getClassName();
389 switch (className) {
390 // TODO make it more configurable
391 // FIXME deal with privileges stacks (in Equinox)
392 case "java.lang.System$Logger":
393 case "java.util.logging.Logger":
394 case "org.apache.commons.logging.Log":
395 case "org.osgi.service.log.Logger":
396 case "org.eclipse.osgi.internal.log.LoggerImpl":
397 case "org.argeo.api.cms.CmsLog":
398 case "org.eclipse.jetty.util.log.Slf4jLog":
399 case "sun.util.logging.internal.LoggingProviderImpl$JULWrapper":
400 case "org.slf4j.impl.ArgeoLogger":
401 case "org.argeo.cms.internal.osgi.CmsOsgiLogger":
402 case "org.argeo.init.osgi.OsgiBootUtils":
403 lowestLoggerInterface = i;
404 continue stack;
405 default:
406 }
407 }
408 if (stack.length > lowestLoggerInterface + 1)
409 callLocation = stack[lowestLoggerInterface + 1];
410 }
411 return callLocation;
412 }
413
414 }
415
416 private final static String KEY_LOGGER = Logger.class.getName();
417 private final static String KEY_LEVEL = Level.class.getName();
418 private final static String KEY_MSG = String.class.getName();
419 private final static String KEY_THROWABLE = Throwable.class.getName();
420 private final static String KEY_INSTANT = Instant.class.getName();
421 private final static String KEY_CALL_LOCATION = StackTraceElement.class.getName();
422 private final static String KEY_THREAD = Thread.class.getName();
423
424 private class LogEntryPublisher extends SubmissionPublisher<Map<String, Serializable>> {
425
426 private LogEntryPublisher() {
427 super();
428 }
429
430 // private void log(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
431 // Thread thread, Throwable thrown, StackTraceElement callLocation) {
432 //
433 // }
434
435 }
436
437 /**
438 * An internal optimisation for collections. It should not be referred to
439 * directly as a type.
440 */
441 // TODO optimise memory with a custom map implementation?
442 // but access may be slower
443 private static class LogEntryMap extends HashMap<String, Serializable> {
444 private static final long serialVersionUID = 7361434381922521356L;
445
446 private final long sequence;
447
448 private LogEntryMap(long sequence) {
449 // maximum 7 fields, so using default load factor 0.75
450 // an initial size of 10 should prevent rehashing (7 / 0.75 ~ 9.333)
451 // see HashMap class description for more details
452 super(10, 0.75f);
453 this.sequence = sequence;
454 }
455
456 @Override
457 public boolean equals(Object o) {
458 if (o instanceof LogEntryMap)
459 return sequence == ((LogEntryMap) o).sequence;
460 else if (o instanceof Map) {
461 Map<?, ?> map = (Map<?, ?>) o;
462 return get(KEY_INSTANT).equals(map.get(KEY_INSTANT)) && get(KEY_THREAD).equals(map.get(KEY_THREAD));
463 } else
464 return false;
465 }
466
467 @Override
468 public int hashCode() {
469 return (int) sequence;
470 }
471
472 }
473
474 private class PrintStreamSubscriber implements Flow.Subscriber<Map<String, Serializable>> {
475 private PrintStream out;
476 private PrintStream err;
477 private int writeToErrLevel = Level.WARNING.getSeverity();
478
479 private Subscription subscription;
480
481 protected PrintStreamSubscriber() {
482 this(System.out, System.err);
483 }
484
485 protected PrintStreamSubscriber(PrintStream out, PrintStream err) {
486 this.out = out;
487 this.err = err;
488 }
489
490 private Level getLevel(Map<String, Serializable> logEntry) {
491 return (Level) logEntry.get(KEY_LEVEL);
492 }
493
494 @Override
495 public void onSubscribe(Subscription subscription) {
496 this.subscription = subscription;
497 this.subscription.request(1);
498 }
499
500 @Override
501 public void onNext(Map<String, Serializable> item) {
502 if (getLevel(item).getSeverity() >= writeToErrLevel) {
503 err.print(toPrint(item));
504 } else {
505 out.print(toPrint(item));
506 }
507 // TODO flush for journald?
508 if (this.subscription != null)
509 this.subscription.request(1);
510 }
511
512 @Override
513 public void onError(Throwable throwable) {
514 throwable.printStackTrace(err);
515 }
516
517 @Override
518 public void onComplete() {
519 out.flush();
520 err.flush();
521 }
522
523 protected String firstLinePrefix(Map<String, Serializable> logEntry) {
524 Level level = getLevel(logEntry);
525 String spaces;
526 switch (level) {
527 case ERROR:
528 case DEBUG:
529 case TRACE:
530 spaces = " ";
531 break;
532 case INFO:
533 spaces = " ";
534 break;
535 case WARNING:
536 spaces = " ";
537 break;
538 case ALL:
539 spaces = " ";
540 break;
541 default:
542 throw new IllegalArgumentException("Unsupported level " + level);
543 }
544 return journald ? linePrefix(logEntry) : logEntry.get(KEY_INSTANT) + " " + level + spaces;
545 }
546
547 protected String firstLineSuffix(Map<String, Serializable> logEntry) {
548 return " - " + (logEntry.containsKey(KEY_CALL_LOCATION) ? logEntry.get(KEY_CALL_LOCATION)
549 : logEntry.get(KEY_LOGGER)) + " [" + logEntry.get(KEY_THREAD) + "]";
550 }
551
552 protected String linePrefix(Map<String, Serializable> logEntry) {
553 return journald ? "<" + levelToJournald(getLevel(logEntry)) + ">" : "";
554 }
555
556 protected int levelToJournald(Level level) {
557 int severity = level.getSeverity();
558 if (severity >= Level.ERROR.getSeverity())
559 return 3;
560 else if (severity >= Level.WARNING.getSeverity())
561 return 4;
562 else if (severity >= Level.INFO.getSeverity())
563 return 6;
564 else
565 return 7;
566 }
567
568 protected String toPrint(Map<String, Serializable> logEntry) {
569 StringBuilder sb = new StringBuilder();
570 StringTokenizer st = new StringTokenizer((String) logEntry.get(KEY_MSG), "\r\n");
571
572 // first line
573 String firstLine = st.hasMoreTokens() ? st.nextToken() : "";
574 sb.append(firstLinePrefix(logEntry));
575 sb.append(firstLine);
576 sb.append(firstLineSuffix(logEntry));
577 sb.append('\n');
578
579 // other lines
580 String prefix = linePrefix(logEntry);
581 while (st.hasMoreTokens()) {
582 sb.append(prefix);
583 sb.append(st.nextToken());
584 sb.append('\n');
585 }
586
587 if (logEntry.containsKey(KEY_THROWABLE)) {
588 Throwable throwable = (Throwable) logEntry.get(KEY_THROWABLE);
589 sb.append(prefix);
590 addThrowable(sb, prefix, throwable);
591 }
592 return sb.toString();
593 }
594
595 protected void addThrowable(StringBuilder sb, String prefix, Throwable throwable) {
596 sb.append(throwable.getClass().getName());
597 sb.append(": ");
598 sb.append(throwable.getMessage());
599 sb.append('\n');
600 for (StackTraceElement ste : throwable.getStackTrace()) {
601 sb.append(prefix);
602 sb.append('\t');
603 sb.append(ste.toString());
604 sb.append('\n');
605 }
606 if (throwable.getCause() != null) {
607 sb.append(prefix);
608 sb.append("Caused by: ");
609 addThrowable(sb, prefix, throwable.getCause());
610 }
611 }
612 }
613
614 // public static void main(String args[]) {
615 // Logger logger = System.getLogger(ThinLogging.class.getName());
616 // logger.log(Logger.Level.ALL, "Log all");
617 // logger.log(Logger.Level.TRACE, "Multi\nline\ntrace");
618 // logger.log(Logger.Level.DEBUG, "Log debug");
619 // logger.log(Logger.Level.INFO, "Log info");
620 // logger.log(Logger.Level.WARNING, "Log warning");
621 // logger.log(Logger.Level.ERROR, "Log exception", new Throwable());
622 //
623 // try {
624 // // we wait a bit in order to make sure all messages are flushed
625 // // TODO synchronize more efficiently
626 // // executor.awaitTermination(300, TimeUnit.MILLISECONDS);
627 // ForkJoinPool.commonPool().awaitTermination(300, TimeUnit.MILLISECONDS);
628 // } catch (InterruptedException e) {
629 // // silent
630 // }
631 //
632 // }
633
634 }