]> git.argeo.org Git - lgpl/argeo-commons.git/blob - org.argeo.init/src/org/argeo/init/logging/ThinLogging.java
Prepare next development cycle
[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.init.RuntimeContext;
33 import org.argeo.init.Service;
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 = 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 = Service.getRuntimeContext();
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 if (!loggers.containsKey(name)) {
195 ThinLogger logger = new ThinLogger(name, computeApplicableLevel(name));
196 loggers.put(name, logger);
197 }
198 return loggers.get(name);
199 }
200
201 public void accept(Map<String, Object> configuration) {
202 synchronized (levels) {
203 updatingConfiguration = true;
204
205 Map<String, Level> backup = new TreeMap<>(levels);
206
207 boolean fullReset = configuration.containsKey(DEFAULT_LEVEL_PROPERTY);
208 try {
209 properties: for (String property : configuration.keySet()) {
210 if (!property.startsWith(LEVEL_PROPERTY_PREFIX))
211 continue properties;
212 String levelStr = configuration.get(property).toString();
213 Level level = Level.valueOf(levelStr);
214 levels.put(property.substring(LEVEL_PROPERTY_PREFIX.length()), level);
215 }
216
217 if (fullReset) {
218 Iterator<Map.Entry<String, Level>> it = levels.entrySet().iterator();
219 while (it.hasNext()) {
220 Map.Entry<String, Level> entry = it.next();
221 String name = entry.getKey();
222 if (!configuration.containsKey(LEVEL_PROPERTY_PREFIX + name)) {
223 it.remove();
224 }
225 }
226 Level newDefaultLevel = Level.valueOf(configuration.get(DEFAULT_LEVEL_PROPERTY).toString());
227 levels.put(DEFAULT_LEVEL_NAME, newDefaultLevel);
228 // TODO notify everyone?
229 }
230 assert levels.containsKey(DEFAULT_LEVEL_NAME);
231
232 // recompute all levels
233 for (String name : loggers.keySet()) {
234 ThinLogger logger = loggers.get(name);
235 logger.setLevel(computeApplicableLevel(name));
236 }
237 } catch (IllegalArgumentException e) {
238 e.printStackTrace();
239 levels.clear();
240 levels.putAll(backup);
241 }
242 updatingConfiguration = false;
243 levels.notifyAll();
244 }
245 }
246
247 Flow.Publisher<Map<String, Serializable>> getLogEntryPublisher() {
248 return publisher;
249 }
250
251 Map<String, Level> getLevels() {
252 return Collections.unmodifiableNavigableMap(levels);
253 }
254
255 private void dispatchLogEntry(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
256 Thread thread, Throwable thrown, StackTraceElement callLocation) {
257 assert level != null;
258 assert logger != null;
259 // assert msg != null;
260 assert instant != null;
261 assert thread != null;
262
263 if (msg == null)
264 msg = "null";
265
266 final long sequence = nextEntry.incrementAndGet();
267
268 Map<String, Serializable> logEntry = new LogEntryMap(sequence);
269
270 // same object as key class name
271 logEntry.put(KEY_LEVEL, level);
272 logEntry.put(KEY_MSG, msg);
273 logEntry.put(KEY_INSTANT, instant);
274 if (thrown != null)
275 logEntry.put(KEY_THROWABLE, thrown);
276 if (callLocation != null)
277 logEntry.put(KEY_CALL_LOCATION, callLocation);
278
279 // object is a string
280 logEntry.put(KEY_LOGGER, logger.getName());
281 logEntry.put(KEY_THREAD, thread.getName());
282
283 // should be unmodifiable for security reasons
284 if (synchronous) {
285 assert synchronousSubscriber != null;
286 synchronousSubscriber.onNext(logEntry);
287 } else {
288 if (!publisher.isClosed())
289 publisher.submit(Collections.unmodifiableMap(logEntry));
290 }
291
292 }
293
294 /*
295 * INTERNAL CLASSES
296 */
297
298 private class ThinLogger implements System.Logger {
299 private final String name;
300
301 private Level level;
302
303 protected ThinLogger(String name, Level level) {
304 assert Objects.nonNull(name);
305 this.name = name;
306 this.level = level;
307 }
308
309 @Override
310 public String getName() {
311 return name;
312 }
313
314 @Override
315 public boolean isLoggable(Level level) {
316 return level.getSeverity() >= getLevel().getSeverity();
317 // TODO optimise by referencing the applicable level in this class?
318 // return ThinLogging.this.isLoggable(name, level);
319 }
320
321 private Level getLevel() {
322 if (updatingConfiguration) {
323 synchronized (levels) {
324 try {
325 levels.wait();
326 // TODO make exit more robust
327 } catch (InterruptedException e) {
328 throw new IllegalStateException(e);
329 }
330 }
331 }
332 return level;
333 }
334
335 @Override
336 public void log(Level level, ResourceBundle bundle, String msg, Throwable thrown) {
337 if (!isLoggable(level))
338 return;
339 // measure timestamp first
340 Instant now = Instant.now();
341 Thread thread = Thread.currentThread();
342 dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, thrown, findCallLocation(level, thread));
343 }
344
345 @Override
346 public void log(Level level, ResourceBundle bundle, String format, Object... params) {
347 if (!isLoggable(level))
348 return;
349 // measure timestamp first
350 Instant now = Instant.now();
351 Thread thread = Thread.currentThread();
352
353 // NOTE: this is the method called when logging a plain message without
354 // exception, so it should be considered as a format only when args are not null
355 // if (format.contains("{}"))// workaround for weird Jetty formatting
356 // params = null;
357 // TODO move this to slf4j wrapper?
358 if (format.contains("{}")) {
359 StringBuilder sb = new StringBuilder();
360 String[] segments = format.split("\\{\\}");
361 for (int i = 0; i < segments.length; i++) {
362 sb.append(segments[i]);
363 if (i != (segments.length - 1))
364 sb.append("{" + i + "}");
365 }
366 format = sb.toString();
367 }
368 String msg = params == null ? format : MessageFormat.format(format, params);
369 dispatchLogEntry(ThinLogger.this, level, bundle, msg, now, thread, (Throwable) null,
370 findCallLocation(level, thread));
371 }
372
373 private void setLevel(Level level) {
374 this.level = level;
375 }
376
377 private StackTraceElement findCallLocation(Level level, Thread thread) {
378 assert level != null;
379 assert thread != null;
380 // TODO rather use a StackWalker and make it smarter
381 StackTraceElement callLocation = null;
382 if (level.getSeverity() >= callLocationLevel.getSeverity()) {
383 StackTraceElement[] stack = thread.getStackTrace();
384 int lowestLoggerInterface = 0;
385 stack: for (int i = 2; i < stack.length; i++) {
386 String className = stack[i].getClassName();
387 switch (className) {
388 // TODO make it more configurable
389 // FIXME deal with privileges stacks (in Equinox)
390 case "java.lang.System$Logger":
391 case "java.util.logging.Logger":
392 case "org.apache.commons.logging.Log":
393 case "org.osgi.service.log.Logger":
394 case "org.eclipse.osgi.internal.log.LoggerImpl":
395 case "org.argeo.api.cms.CmsLog":
396 case "org.argeo.init.osgi.OsgiBootUtils":
397 case "org.slf4j.impl.ArgeoLogger":
398 case "org.argeo.cms.internal.osgi.CmsOsgiLogger":
399 case "org.eclipse.jetty.util.log.Slf4jLog":
400 case "sun.util.logging.internal.LoggingProviderImpl$JULWrapper":
401 lowestLoggerInterface = i;
402 continue stack;
403 default:
404 }
405 }
406 if (stack.length > lowestLoggerInterface + 1)
407 callLocation = stack[lowestLoggerInterface + 1];
408 }
409 return callLocation;
410 }
411
412 }
413
414 private final static String KEY_LOGGER = Logger.class.getName();
415 private final static String KEY_LEVEL = Level.class.getName();
416 private final static String KEY_MSG = String.class.getName();
417 private final static String KEY_THROWABLE = Throwable.class.getName();
418 private final static String KEY_INSTANT = Instant.class.getName();
419 private final static String KEY_CALL_LOCATION = StackTraceElement.class.getName();
420 private final static String KEY_THREAD = Thread.class.getName();
421
422 private class LogEntryPublisher extends SubmissionPublisher<Map<String, Serializable>> {
423
424 private LogEntryPublisher() {
425 super();
426 }
427
428 // private void log(ThinLogger logger, Level level, ResourceBundle bundle, String msg, Instant instant,
429 // Thread thread, Throwable thrown, StackTraceElement callLocation) {
430 //
431 // }
432
433 }
434
435 /**
436 * An internal optimisation for collections. It should not be referred to
437 * directly as a type.
438 */
439 // TODO optimise memory with a custom map implementation?
440 // but access may be slower
441 private static class LogEntryMap extends HashMap<String, Serializable> {
442 private static final long serialVersionUID = 7361434381922521356L;
443
444 private final long sequence;
445
446 private LogEntryMap(long sequence) {
447 // maximum 7 fields, so using default load factor 0.75
448 // an initial size of 10 should prevent rehashing (7 / 0.75 ~ 9.333)
449 // see HashMap class description for more details
450 super(10, 0.75f);
451 this.sequence = sequence;
452 }
453
454 @Override
455 public boolean equals(Object o) {
456 if (o instanceof LogEntryMap)
457 return sequence == ((LogEntryMap) o).sequence;
458 else if (o instanceof Map) {
459 Map<?, ?> map = (Map<?, ?>) o;
460 return get(KEY_INSTANT).equals(map.get(KEY_INSTANT)) && get(KEY_THREAD).equals(map.get(KEY_THREAD));
461 } else
462 return false;
463 }
464
465 @Override
466 public int hashCode() {
467 return (int) sequence;
468 }
469
470 }
471
472 private class PrintStreamSubscriber implements Flow.Subscriber<Map<String, Serializable>> {
473 private PrintStream out;
474 private PrintStream err;
475 private int writeToErrLevel = Level.WARNING.getSeverity();
476
477 private Subscription subscription;
478
479 protected PrintStreamSubscriber() {
480 this(System.out, System.err);
481 }
482
483 protected PrintStreamSubscriber(PrintStream out, PrintStream err) {
484 this.out = out;
485 this.err = err;
486 }
487
488 private Level getLevel(Map<String, Serializable> logEntry) {
489 return (Level) logEntry.get(KEY_LEVEL);
490 }
491
492 @Override
493 public void onSubscribe(Subscription subscription) {
494 this.subscription = subscription;
495 this.subscription.request(1);
496 }
497
498 @Override
499 public void onNext(Map<String, Serializable> item) {
500 if (getLevel(item).getSeverity() >= writeToErrLevel) {
501 err.print(toPrint(item));
502 } else {
503 out.print(toPrint(item));
504 }
505 // TODO flush for journald?
506 if (this.subscription != null)
507 this.subscription.request(1);
508 }
509
510 @Override
511 public void onError(Throwable throwable) {
512 throwable.printStackTrace(err);
513 }
514
515 @Override
516 public void onComplete() {
517 out.flush();
518 err.flush();
519 }
520
521 protected String firstLinePrefix(Map<String, Serializable> logEntry) {
522 Level level = getLevel(logEntry);
523 String spaces;
524 switch (level) {
525 case ERROR:
526 case DEBUG:
527 case TRACE:
528 spaces = " ";
529 break;
530 case INFO:
531 spaces = " ";
532 break;
533 case WARNING:
534 spaces = " ";
535 break;
536 case ALL:
537 spaces = " ";
538 break;
539 default:
540 throw new IllegalArgumentException("Unsupported level " + level);
541 }
542 return journald ? linePrefix(logEntry) : logEntry.get(KEY_INSTANT) + " " + level + spaces;
543 }
544
545 protected String firstLineSuffix(Map<String, Serializable> logEntry) {
546 return " - " + (logEntry.containsKey(KEY_CALL_LOCATION) ? logEntry.get(KEY_CALL_LOCATION)
547 : logEntry.get(KEY_LOGGER)) + " [" + logEntry.get(KEY_THREAD) + "]";
548 }
549
550 protected String linePrefix(Map<String, Serializable> logEntry) {
551 return journald ? "<" + levelToJournald(getLevel(logEntry)) + ">" : "";
552 }
553
554 protected int levelToJournald(Level level) {
555 int severity = level.getSeverity();
556 if (severity >= Level.ERROR.getSeverity())
557 return 3;
558 else if (severity >= Level.WARNING.getSeverity())
559 return 4;
560 else if (severity >= Level.INFO.getSeverity())
561 return 6;
562 else
563 return 7;
564 }
565
566 protected String toPrint(Map<String, Serializable> logEntry) {
567 StringBuilder sb = new StringBuilder();
568 StringTokenizer st = new StringTokenizer((String) logEntry.get(KEY_MSG), "\r\n");
569
570 // first line
571 String firstLine = st.hasMoreTokens() ? st.nextToken() : "";
572 sb.append(firstLinePrefix(logEntry));
573 sb.append(firstLine);
574 sb.append(firstLineSuffix(logEntry));
575 sb.append('\n');
576
577 // other lines
578 String prefix = linePrefix(logEntry);
579 while (st.hasMoreTokens()) {
580 sb.append(prefix);
581 sb.append(st.nextToken());
582 sb.append('\n');
583 }
584
585 if (logEntry.containsKey(KEY_THROWABLE)) {
586 Throwable throwable = (Throwable) logEntry.get(KEY_THROWABLE);
587 sb.append(prefix);
588 addThrowable(sb, prefix, throwable);
589 }
590 return sb.toString();
591 }
592
593 protected void addThrowable(StringBuilder sb, String prefix, Throwable throwable) {
594 sb.append(throwable.getClass().getName());
595 sb.append(": ");
596 sb.append(throwable.getMessage());
597 sb.append('\n');
598 for (StackTraceElement ste : throwable.getStackTrace()) {
599 sb.append(prefix);
600 sb.append('\t');
601 sb.append(ste.toString());
602 sb.append('\n');
603 }
604 if (throwable.getCause() != null) {
605 sb.append(prefix);
606 sb.append("Caused by: ");
607 addThrowable(sb, prefix, throwable.getCause());
608 }
609 }
610 }
611
612 public static void main(String args[]) {
613 Logger logger = System.getLogger(ThinLogging.class.getName());
614 logger.log(Logger.Level.ALL, "Log all");
615 logger.log(Logger.Level.TRACE, "Multi\nline\ntrace");
616 logger.log(Logger.Level.DEBUG, "Log debug");
617 logger.log(Logger.Level.INFO, "Log info");
618 logger.log(Logger.Level.WARNING, "Log warning");
619 logger.log(Logger.Level.ERROR, "Log exception", new Throwable());
620
621 try {
622 // we ait a bit in order to make sure all messages are flushed
623 // TODO synchronize more efficiently
624 // executor.awaitTermination(300, TimeUnit.MILLISECONDS);
625 ForkJoinPool.commonPool().awaitTermination(300, TimeUnit.MILLISECONDS);
626 } catch (InterruptedException e) {
627 // silent
628 }
629
630 }
631
632 }