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