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