org.argeo.init/src/org/argeo/init/logging/ThinLogging.java

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