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