org.argeo.cms/src/org/argeo/cms/internal/kernel/NodeLogger.java

   1 /*
   2  * Copyright (C) 2007-2012 Argeo GmbH
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *         http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16 package org.argeo.cms.internal.kernel;
  17
  18 import java.io.IOException;
  19 import java.net.URI;
  20 import java.nio.file.FileSystems;
  21 import java.nio.file.Path;
  22 import java.nio.file.Paths;
  23 import java.nio.file.StandardWatchEventKinds;
  24 import java.nio.file.WatchEvent;
  25 import java.nio.file.WatchKey;
  26 import java.nio.file.WatchService;
  27 import java.security.SignatureException;
  28 import java.util.ArrayList;
  29 import java.util.Collections;
  30 import java.util.Enumeration;
  31 import java.util.HashMap;
  32 import java.util.Iterator;
  33 import java.util.LinkedList;
  34 import java.util.List;
  35 import java.util.ListIterator;
  36 import java.util.Map;
  37 import java.util.Properties;
  38 import java.util.concurrent.BlockingQueue;
  39 import java.util.concurrent.LinkedBlockingQueue;
  40
  41 import org.apache.commons.logging.Log;
  42 import org.apache.commons.logging.LogFactory;
  43 import org.apache.log4j.AppenderSkeleton;
  44 import org.apache.log4j.Level;
  45 import org.apache.log4j.LogManager;
  46 import org.apache.log4j.Logger;
  47 import org.apache.log4j.PropertyConfigurator;
  48 import org.apache.log4j.spi.LoggingEvent;
  49 import org.argeo.cms.CmsException;
  50 import org.argeo.cms.auth.CurrentUser;
  51 import org.argeo.node.ArgeoLogListener;
  52 import org.argeo.node.ArgeoLogger;
  53 import org.argeo.node.NodeConstants;
  54 import org.argeo.osgi.useradmin.UserAdminConf;
  55 import org.osgi.framework.Bundle;
  56 import org.osgi.framework.Constants;
  57 import org.osgi.framework.ServiceReference;
  58 import org.osgi.service.cm.ConfigurationAdmin;
  59 import org.osgi.service.log.LogEntry;
  60 import org.osgi.service.log.LogLevel;
  61 import org.osgi.service.log.LogListener;
  62 import org.osgi.service.log.LogReaderService;
  63
  64 /** Not meant to be used directly in standard log4j config */
  65 class NodeLogger implements ArgeoLogger, LogListener {
  66         /** Internal debug for development purposes. */
  67         private static Boolean debug = false;
  68
  69         // private final static Log log = LogFactory.getLog(NodeLogger.class);
  70
  71         private Boolean disabled = false;
  72
  73         private String level = null;
  74
  75         private Level log4jLevel = null;
  76         // private Layout layout;
  77
  78         private Properties configuration;
  79
  80         private AppenderImpl appender;
  81
  82         private final List<ArgeoLogListener> everythingListeners = Collections
  83                         .synchronizedList(new ArrayList<ArgeoLogListener>());
  84         private final List<ArgeoLogListener> allUsersListeners = Collections
  85                         .synchronizedList(new ArrayList<ArgeoLogListener>());
  86         private final Map<String, List<ArgeoLogListener>> userListeners = Collections
  87                         .synchronizedMap(new HashMap<String, List<ArgeoLogListener>>());
  88
  89         private BlockingQueue<LogEvent> events;
  90         private LogDispatcherThread logDispatcherThread = new LogDispatcherThread();
  91
  92         private Integer maxLastEventsCount = 10 * 1000;
  93
  94         /** Marker to prevent stack overflow */
  95         private ThreadLocal<Boolean> dispatching = new ThreadLocal<Boolean>() {
  96
  97                 @Override
  98                 protected Boolean initialValue() {
  99                         return false;
 100                 }
 101         };
 102
 103         public NodeLogger(LogReaderService lrs) {
 104                 Enumeration<LogEntry> logEntries = lrs.getLog();
 105                 while (logEntries.hasMoreElements())
 106                         logged(logEntries.nextElement());
 107                 lrs.addLogListener(this);
 108
 109                 // configure log4j watcher
 110                 String log4jConfiguration = KernelUtils.getFrameworkProp("log4j.configuration");
 111                 if (log4jConfiguration != null && log4jConfiguration.startsWith("file:")) {
 112                         if (log4jConfiguration.contains("..")) {
 113                                 if (log4jConfiguration.startsWith("file://"))
 114                                         log4jConfiguration = log4jConfiguration.substring("file://".length());
 115                                 else if (log4jConfiguration.startsWith("file:"))
 116                                         log4jConfiguration = log4jConfiguration.substring("file:".length());
 117                         }
 118                         try {
 119                                 Path log4jconfigPath;
 120                                 if (log4jConfiguration.startsWith("file:"))
 121                                         log4jconfigPath = Paths.get(new URI(log4jConfiguration));
 122                                 else
 123                                         log4jconfigPath = Paths.get(log4jConfiguration);
 124                                 Thread log4jConfWatcher = new Log4jConfWatcherThread(log4jconfigPath);
 125                                 log4jConfWatcher.start();
 126                         } catch (Exception e) {
 127                                 stdErr("Badly formatted log4j configuration URI " + log4jConfiguration + ": " + e.getMessage());
 128                         }
 129                 }
 130         }
 131
 132         public void init() {
 133                 try {
 134                         events = new LinkedBlockingQueue<LogEvent>();
 135
 136                         // if (layout != null)
 137                         // setLayout(layout);
 138                         // else
 139                         // setLayout(new PatternLayout(pattern));
 140                         appender = new AppenderImpl();
 141                         reloadConfiguration();
 142                         Logger.getRootLogger().addAppender(appender);
 143
 144                         logDispatcherThread = new LogDispatcherThread();
 145                         logDispatcherThread.start();
 146                 } catch (Exception e) {
 147                         throw new CmsException("Cannot initialize log4j");
 148                 }
 149         }
 150
 151         public void destroy() throws Exception {
 152                 Logger.getRootLogger().removeAppender(appender);
 153                 allUsersListeners.clear();
 154                 for (List<ArgeoLogListener> lst : userListeners.values())
 155                         lst.clear();
 156                 userListeners.clear();
 157
 158                 events.clear();
 159                 events = null;
 160                 logDispatcherThread.interrupt();
 161         }
 162
 163         // public void setLayout(Layout layout) {
 164         // this.layout = layout;
 165         // }
 166
 167         public String toString() {
 168                 return "Node Logger";
 169         }
 170
 171         //
 172         // OSGi LOGGER
 173         //
 174         @Override
 175         public void logged(LogEntry status) {
 176                 Log pluginLog = LogFactory.getLog(status.getBundle().getSymbolicName());
 177                 LogLevel severity = status.getLogLevel();
 178                 if (severity.equals(LogLevel.ERROR) && pluginLog.isErrorEnabled()) {
 179                         // FIXME Fix Argeo TP
 180                         if (status.getException() instanceof SignatureException)
 181                                 return;
 182                         pluginLog.error(msg(status), status.getException());
 183                 } else if (severity.equals(LogLevel.WARN) && pluginLog.isWarnEnabled()) {
 184                         if (pluginLog.isTraceEnabled())
 185                                 pluginLog.warn(msg(status), status.getException());
 186                         else
 187                                 pluginLog.warn(msg(status));
 188                 } else if (severity.equals(LogLevel.INFO) && pluginLog.isDebugEnabled())
 189                         pluginLog.debug(msg(status), status.getException());
 190                 else if (severity.equals(LogLevel.DEBUG) && pluginLog.isTraceEnabled())
 191                         pluginLog.trace(msg(status), status.getException());
 192                 else if (severity.equals(LogLevel.TRACE) && pluginLog.isTraceEnabled())
 193                         pluginLog.trace(msg(status), status.getException());
 194         }
 195
 196         private String msg(LogEntry status) {
 197                 StringBuilder sb = new StringBuilder();
 198                 sb.append(status.getMessage());
 199                 Bundle bundle = status.getBundle();
 200                 if (bundle != null) {
 201                         sb.append(" '" + bundle.getSymbolicName() + "'");
 202                 }
 203                 ServiceReference<?> sr = status.getServiceReference();
 204                 if (sr != null) {
 205                         sb.append(' ');
 206                         String[] objectClasses = (String[]) sr.getProperty(Constants.OBJECTCLASS);
 207                         if (isSpringApplicationContext(objectClasses)) {
 208                                 sb.append("{org.springframework.context.ApplicationContext}");
 209                                 Object symbolicName = sr.getProperty(Constants.BUNDLE_SYMBOLICNAME);
 210                                 if (symbolicName != null)
 211                                         sb.append(" " + Constants.BUNDLE_SYMBOLICNAME + ": " + symbolicName);
 212                         } else {
 213                                 sb.append(arrayToString(objectClasses));
 214                         }
 215                         Object cn = sr.getProperty(NodeConstants.CN);
 216                         if (cn != null)
 217                                 sb.append(" " + NodeConstants.CN + ": " + cn);
 218                         Object factoryPid = sr.getProperty(ConfigurationAdmin.SERVICE_FACTORYPID);
 219                         if (factoryPid != null)
 220                                 sb.append(" " + ConfigurationAdmin.SERVICE_FACTORYPID + ": " + factoryPid);
 221                         // else {
 222                         // Object servicePid = sr.getProperty(Constants.SERVICE_PID);
 223                         // if (servicePid != null)
 224                         // sb.append(" " + Constants.SERVICE_PID + ": " + servicePid);
 225                         // }
 226                         // servlets
 227                         Object whiteBoardPattern = sr.getProperty(KernelConstants.WHITEBOARD_PATTERN_PROP);
 228                         if (whiteBoardPattern != null) {
 229                                 if (whiteBoardPattern instanceof String) {
 230                                         sb.append(" " + KernelConstants.WHITEBOARD_PATTERN_PROP + ": " + whiteBoardPattern);
 231                                 } else {
 232                                         sb.append(" " + KernelConstants.WHITEBOARD_PATTERN_PROP + ": "
 233                                                         + arrayToString((String[]) whiteBoardPattern));
 234                                 }
 235                         }
 236                         // RWT
 237                         Object contextName = sr.getProperty(KernelConstants.CONTEXT_NAME_PROP);
 238                         if (contextName != null)
 239                                 sb.append(" " + KernelConstants.CONTEXT_NAME_PROP + ": " + contextName);
 240
 241                         // user directories
 242                         Object baseDn = sr.getProperty(UserAdminConf.baseDn.name());
 243                         if (baseDn != null)
 244                                 sb.append(" " + UserAdminConf.baseDn.name() + ": " + baseDn);
 245
 246                 }
 247                 return sb.toString();
 248         }
 249
 250         private String arrayToString(Object[] arr) {
 251                 StringBuilder sb = new StringBuilder();
 252                 sb.append('[');
 253                 for (int i = 0; i < arr.length; i++) {
 254                         if (i != 0)
 255                                 sb.append(',');
 256                         sb.append(arr[i]);
 257                 }
 258                 sb.append(']');
 259                 return sb.toString();
 260         }
 261
 262         private boolean isSpringApplicationContext(String[] objectClasses) {
 263                 for (String clss : objectClasses) {
 264                         if (clss.equals("org.eclipse.gemini.blueprint.context.DelegatedExecutionOsgiBundleApplicationContext")) {
 265                                 return true;
 266                         }
 267                 }
 268                 return false;
 269         }
 270
 271         //
 272         // ARGEO LOGGER
 273         //
 274
 275         public synchronized void register(ArgeoLogListener listener, Integer numberOfPreviousEvents) {
 276                 String username = CurrentUser.getUsername();
 277                 if (username == null)
 278                         throw new CmsException("Only authenticated users can register a log listener");
 279
 280                 if (!userListeners.containsKey(username)) {
 281                         List<ArgeoLogListener> lst = Collections.synchronizedList(new ArrayList<ArgeoLogListener>());
 282                         userListeners.put(username, lst);
 283                 }
 284                 userListeners.get(username).add(listener);
 285                 List<LogEvent> lastEvents = logDispatcherThread.getLastEvents(username, numberOfPreviousEvents);
 286                 for (LogEvent evt : lastEvents)
 287                         dispatchEvent(listener, evt);
 288         }
 289
 290         public synchronized void registerForAll(ArgeoLogListener listener, Integer numberOfPreviousEvents,
 291                         boolean everything) {
 292                 if (everything)
 293                         everythingListeners.add(listener);
 294                 else
 295                         allUsersListeners.add(listener);
 296                 List<LogEvent> lastEvents = logDispatcherThread.getLastEvents(null, numberOfPreviousEvents);
 297                 for (LogEvent evt : lastEvents)
 298                         if (everything || evt.getUsername() != null)
 299                                 dispatchEvent(listener, evt);
 300         }
 301
 302         public synchronized void unregister(ArgeoLogListener listener) {
 303                 String username = CurrentUser.getUsername();
 304                 if (username == null)// FIXME
 305                         return;
 306                 if (!userListeners.containsKey(username))
 307                         throw new CmsException("No user listeners " + listener + " registered for user " + username);
 308                 if (!userListeners.get(username).contains(listener))
 309                         throw new CmsException("No user listeners " + listener + " registered for user " + username);
 310                 userListeners.get(username).remove(listener);
 311                 if (userListeners.get(username).isEmpty())
 312                         userListeners.remove(username);
 313
 314         }
 315
 316         public synchronized void unregisterForAll(ArgeoLogListener listener) {
 317                 everythingListeners.remove(listener);
 318                 allUsersListeners.remove(listener);
 319         }
 320
 321         /** For development purpose, since using regular logging is not easy here */
 322         private static void stdOut(Object obj) {
 323                 System.out.println(obj);
 324         }
 325
 326         private static void stdErr(Object obj) {
 327                 System.err.println(obj);
 328         }
 329
 330         private static void debug(Object obj) {
 331                 if (debug)
 332                         System.out.println(obj);
 333         }
 334
 335         private static boolean isInternalDebugEnabled() {
 336                 return debug;
 337         }
 338
 339         // public void setPattern(String pattern) {
 340         // this.pattern = pattern;
 341         // }
 342
 343         public void setDisabled(Boolean disabled) {
 344                 this.disabled = disabled;
 345         }
 346
 347         public void setLevel(String level) {
 348                 this.level = level;
 349         }
 350
 351         public void setConfiguration(Properties configuration) {
 352                 this.configuration = configuration;
 353         }
 354
 355         public void updateConfiguration(Properties configuration) {
 356                 setConfiguration(configuration);
 357                 reloadConfiguration();
 358         }
 359
 360         public Properties getConfiguration() {
 361                 return configuration;
 362         }
 363
 364         /**
 365          * Reloads configuration (if the configuration {@link Properties} is set)
 366          */
 367         protected void reloadConfiguration() {
 368                 if (configuration != null) {
 369                         LogManager.resetConfiguration();
 370                         PropertyConfigurator.configure(configuration);
 371                 }
 372         }
 373
 374         protected synchronized void processLoggingEvent(LogEvent event) {
 375                 if (disabled)
 376                         return;
 377
 378                 if (dispatching.get())
 379                         return;
 380
 381                 if (level != null && !level.trim().equals("")) {
 382                         if (log4jLevel == null || !log4jLevel.toString().equals(level))
 383                                 try {
 384                                         log4jLevel = Level.toLevel(level);
 385                                 } catch (Exception e) {
 386                                         System.err.println("Log4j level could not be set for level '" + level + "', resetting it to null.");
 387                                         e.printStackTrace();
 388                                         level = null;
 389                                 }
 390
 391                         if (log4jLevel != null && !event.getLoggingEvent().getLevel().isGreaterOrEqual(log4jLevel)) {
 392                                 return;
 393                         }
 394                 }
 395
 396                 try {
 397                         // admin listeners
 398                         Iterator<ArgeoLogListener> everythingIt = everythingListeners.iterator();
 399                         while (everythingIt.hasNext())
 400                                 dispatchEvent(everythingIt.next(), event);
 401
 402                         if (event.getUsername() != null) {
 403                                 Iterator<ArgeoLogListener> allUsersIt = allUsersListeners.iterator();
 404                                 while (allUsersIt.hasNext())
 405                                         dispatchEvent(allUsersIt.next(), event);
 406
 407                                 if (userListeners.containsKey(event.getUsername())) {
 408                                         Iterator<ArgeoLogListener> userIt = userListeners.get(event.getUsername()).iterator();
 409                                         while (userIt.hasNext())
 410                                                 dispatchEvent(userIt.next(), event);
 411                                 }
 412                         }
 413                 } catch (Exception e) {
 414                         stdOut("Cannot process logging event");
 415                         e.printStackTrace();
 416                 }
 417         }
 418
 419         protected void dispatchEvent(ArgeoLogListener logListener, LogEvent evt) {
 420                 LoggingEvent event = evt.getLoggingEvent();
 421                 logListener.appendLog(evt.getUsername(), event.getTimeStamp(), event.getLevel().toString(),
 422                                 event.getLoggerName(), event.getThreadName(), event.getMessage(), event.getThrowableStrRep());
 423         }
 424
 425         private class AppenderImpl extends AppenderSkeleton {
 426                 public boolean requiresLayout() {
 427                         return false;
 428                 }
 429
 430                 public void close() {
 431                 }
 432
 433                 @Override
 434                 protected void append(LoggingEvent event) {
 435                         if (events != null) {
 436                                 try {
 437                                         String username = CurrentUser.getUsername();
 438                                         events.put(new LogEvent(username, event));
 439                                 } catch (InterruptedException e) {
 440                                         // silent
 441                                 }
 442                         }
 443                 }
 444
 445         }
 446
 447         private class LogDispatcherThread extends Thread {
 448                 /** encapsulated in order to simplify concurrency management */
 449                 private LinkedList<LogEvent> lastEvents = new LinkedList<LogEvent>();
 450
 451                 public LogDispatcherThread() {
 452                         super("Argeo Logging Dispatcher Thread");
 453                 }
 454
 455                 public void run() {
 456                         while (events != null) {
 457                                 try {
 458                                         LogEvent loggingEvent = events.take();
 459                                         processLoggingEvent(loggingEvent);
 460                                         addLastEvent(loggingEvent);
 461                                 } catch (InterruptedException e) {
 462                                         if (events == null)
 463                                                 return;
 464                                 }
 465                         }
 466                 }
 467
 468                 protected synchronized void addLastEvent(LogEvent loggingEvent) {
 469                         if (lastEvents.size() >= maxLastEventsCount)
 470                                 lastEvents.poll();
 471                         lastEvents.add(loggingEvent);
 472                 }
 473
 474                 public synchronized List<LogEvent> getLastEvents(String username, Integer maxCount) {
 475                         LinkedList<LogEvent> evts = new LinkedList<LogEvent>();
 476                         ListIterator<LogEvent> it = lastEvents.listIterator(lastEvents.size());
 477                         int count = 0;
 478                         while (it.hasPrevious() && (count < maxCount)) {
 479                                 LogEvent evt = it.previous();
 480                                 if (username == null || username.equals(evt.getUsername())) {
 481                                         evts.push(evt);
 482                                         count++;
 483                                 }
 484                         }
 485                         return evts;
 486                 }
 487         }
 488
 489         private class LogEvent {
 490                 private final String username;
 491                 private final LoggingEvent loggingEvent;
 492
 493                 public LogEvent(String username, LoggingEvent loggingEvent) {
 494                         super();
 495                         this.username = username;
 496                         this.loggingEvent = loggingEvent;
 497                 }
 498
 499                 @Override
 500                 public int hashCode() {
 501                         return loggingEvent.hashCode();
 502                 }
 503
 504                 @Override
 505                 public boolean equals(Object obj) {
 506                         return loggingEvent.equals(obj);
 507                 }
 508
 509                 @Override
 510                 public String toString() {
 511                         return username + "@ " + loggingEvent.toString();
 512                 }
 513
 514                 public String getUsername() {
 515                         return username;
 516                 }
 517
 518                 public LoggingEvent getLoggingEvent() {
 519                         return loggingEvent;
 520                 }
 521
 522         }
 523
 524         private class Log4jConfWatcherThread extends Thread {
 525                 private Path log4jConfigurationPath;
 526
 527                 public Log4jConfWatcherThread(Path log4jConfigurationPath) {
 528                         super("Log4j Configuration Watcher");
 529                         try {
 530                                 this.log4jConfigurationPath = log4jConfigurationPath.toRealPath();
 531                         } catch (IOException e) {
 532                                 this.log4jConfigurationPath = log4jConfigurationPath.toAbsolutePath();
 533                                 stdOut("Cannot determine real path for " + log4jConfigurationPath + ": " + e.getMessage());
 534                         }
 535                 }
 536
 537                 public void run() {
 538                         Path parentDir = log4jConfigurationPath.getParent();
 539                         try (final WatchService watchService = FileSystems.getDefault().newWatchService()) {
 540                                 parentDir.register(watchService, StandardWatchEventKinds.ENTRY_MODIFY);
 541                                 WatchKey wk;
 542                                 watching: while ((wk = watchService.take()) != null) {
 543                                         for (WatchEvent<?> event : wk.pollEvents()) {
 544                                                 final Path changed = (Path) event.context();
 545                                                 if (log4jConfigurationPath.equals(parentDir.resolve(changed))) {
 546                                                         if (isInternalDebugEnabled())
 547                                                                 debug(log4jConfigurationPath + " has changed, reloading.");
 548                                                         PropertyConfigurator.configure(log4jConfigurationPath.toUri().toURL());
 549                                                 }
 550                                         }
 551                                         // reset the key
 552                                         boolean valid = wk.reset();
 553                                         if (!valid) {
 554                                                 break watching;
 555                                         }
 556                                 }
 557                         } catch (IOException | InterruptedException e) {
 558                                 stdErr("Log4j configuration watcher failed: " + e.getMessage());
 559                         }
 560                 }
 561         }
 562 }