Centralized Liferay Logging

When managing a cluster or even a single node, centralized logging can make your devops experience better.

Introduction

I have helped many companies and organizations install Liferay (5, 6 and now 7/DXP), but often times they will stop there. I mean, once the app servers are up and serving traffic correctly, aspects like the log file(s) are ignored. Well, at least as long as everything is operating smoothly; when something has gone wrong, the log file(s) is (are) one of the first places you want to look for issue identification.

Accessing those logs can be tricky; often times the folks that need the logs to complete the analysis are not the system administrators with access to the files themselves.

And the worst part, there is sometimes information generated in the logs which could, if monitored, signal in advance that trouble is brewing. But without monitoring, those signs are not captured and the proactive opportunity to address issues is lost, and later turn into reactive response to failure (if they are reported at all).

Both of these issues (and more) can actually be addressed using a centralized logging solution.

I'm going to present here how I have used the ELK stack to centralize logging, provide dashboards and make logging details available to those that need access.

ELK (Plus)

In case you're not aware, ELK represents the Elasticsearch + Logstash + Kibana tools from Elastic. Logstash is used to collect and ship the logs, Elasticsearch stores and indexes the individual log messages, and Kibana is a visualization platform for ES that can be used to search logs, build dashboard charts, etc based upon the indexed log data.

So I recommend ELK Plus, the plus being the addition of Filebeat (Elastic) and sometimes Kafka (Apache).

Filebeat is a lightweight agent that is used to ship logs to a managed Logstash instance. Rather than having the heavier Logstash application on each Liferay node, the Filebeats lightweight agent can be used to forward log data to a Logstash instance on another host.

Sometimes I also recommend integrating Kafka into the mix. If you are going all-in on logging centralization beyond just Liferay logs, adding a streaming messaging platform like Kafka can help reduce some of the inter-system network traffic between all of the Filebeat hosts and the Logstash instance.

The basic flow for our logging messages will be:

Liferay Logging Preparation

So one concern with Log4j output (the internal logging framework used by Liferay) is that log messages in the regular text file will be multi-line messages. For example, if you log a stack trace, it is logged as separate lines per stack entry. This is fine for viewing a log directly, but from a centralized logging perspective, it means the log file has to be parsed to identify a main log line as well as any optional additional lines that should belong to the message.

Personally, I have a problem with building out a process to parse a log file that I'm actually in control of, so I tend to avoid this kind of configuration. If you really want to just use OOTB log formats, you might take a look at examples such as https://facingissuesonit.com/filebeat-configuration-changes-for-multiline-logs-handlling/ which share how to configure for multi-line messages.

Me, I prefer to export log messages in JSON format using https://github.com/logstash/log4j-jsonevent-layout layout. Generating the log right into JSON means Filebeat (and others) will not need to parse the message in order to use it. Filtering will also be easier and faster since the filters are based off of fields that are already known rather than data parsed out of a text message.

To use the layout, you can either build from source or you could grab a prebuilt version from Maven (https://mvnrepository.com/artifact/net.logstash.log4j/jsonevent-layout). In either case, your jar will need to be deployed into Liferay and, much to my chagrin, I have to recommend building out an EXT plugin for this. Yes, EXT is deprecated, but we're doing a very specific addition here that is just not possible using any other plugin.

Whichever method you choose, be sure to deploy the json-smart library as well, such as deploying the prebuilt jar from https://mvnrepository.com/artifact/net.minidev/json-smart/1.1.1 as it is a dependency of the jsonevent-layout library.

With this new layout jar, we also need to deploy a Liferay log4j configuration override. We can push this in the EXT by creating a ROOT/WEB-INF/classes/META-INF/portal-logj4-ext.xml file. Our file will contain the following:

<?xml version="1.0" ?>
<!DOCTYPE log4j:configuration PUBLIC
  "-//APACHE//DTD LOG4J 1.2//EN" "http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/xml/doc-files/log4j.dtd">

<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' >
  <appender class="org.apache.log4j.rolling.RollingFileAppender" name="JSON_FILE">
    <rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
      <param name="FileNamePattern" value="@liferay.home@/logs/liferay@spi.id@.%d{yyyy-MM-dd}.json.log" />
    </rollingPolicy>
		
    <layout class="net.logstash.log4j.JSONEventLayoutV1" />
  </appender>

  <root>
    <priority value="TRACE" />
    <appender-ref ref="JSON_FILE" />
  </root>
</log4j:configuration>

This defines a new Log4j Appender using the Rolling File Appender, but it also using the JSONEventLayoutV1 layout which generates a single line JSON message record.

With our EXT plugin built and deployed (and environment restarted), we'll start getting a new log file w/ JSON such as the following:

{"@timestamp":"2019-01-16T23:32:31.248Z","source_host":"dnebook","file":"ThreadPool.java","method":"rebuild","level":"DEBUG","line_number":"552","thread_name":"localhost-startStop-1","@version":1,"logger_name":"org.elasticsearch.threadpool","message":"[Hardcase] creating thread_pool [snapshot], type [scaling], min [1], size [4], keep_alive [5m]","class":"org.elasticsearch.threadpool.ThreadPool","mdc":{}}
{"exception":{"stacktrace":"java.lang.ClassNotFoundException: com.github.mustachejava.Mustache cannot be found by com.liferay.portal.search.elasticsearch_2.1.33\n\tat org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:444)\n\tat org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:357)\n\tat org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:349)\n\tat org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)\n\tat java.lang.ClassLoader.loadClass(ClassLoader.java:357)\n\tat java.lang.Class.forName0(Native Method)\n\tat java.lang.Class.forName(Class.java:264)\n\tat org.elasticsearch.script.ScriptModule.configure(ScriptModule.java:80)\n\tat org.elasticsearch.common.inject.AbstractModule.configure(AbstractModule.java:60)\n\tat org.elasticsearch.common.inject.spi.Elements$RecordingBinder.install(Elements.java:233)\n\tat org.elasticsearch.common.inject.spi.Elements.getElements(Elements.java:105)\n\tat org.elasticsearch.common.inject.InjectorShell$Builder.build(InjectorShell.java:143)\n\tat org.elasticsearch.common.inject.InjectorBuilder.build(InjectorBuilder.java:99)\n\tat org.elasticsearch.common.inject.Guice.createInjector(Guice.java:93)\n\tat org.elasticsearch.common.inject.Guice.createInjector(Guice.java:70)\n\tat org.elasticsearch.common.inject.ModulesBuilder.createInjector(ModulesBuilder.java:46)\n\tat org.elasticsearch.node.Node.(Node.java:213)\n\tat org.elasticsearch.node.Node.(Node.java:140)\n\tat org.elasticsearch.node.NodeBuilder.build(NodeBuilder.java:143)\n\tat com.liferay.portal.search.elasticsearch.internal.connection.EmbeddedElasticsearchConnection.createEmbeddedElasticsearchNode(EmbeddedElasticsearchConnection.java:382)\n\tat com.liferay.portal.search.elasticsearch.internal.connection.EmbeddedElasticsearchConnection.createNode(EmbeddedElasticsearchConnection.java:408)\n\tat com.liferay.portal.search.elasticsearch.internal.connection.EmbeddedElasticsearchConnection.createClient(EmbeddedElasticsearchConnection.java:356)\n\tat com.liferay.portal.search.elasticsearch.internal.connection.BaseElasticsearchConnection.connect(BaseElasticsearchConnection.java:68)\n\tat com.liferay.portal.search.elasticsearch.internal.connection.ElasticsearchConnectionManager.connect(ElasticsearchConnectionManager.java:51)\n\tat com.liferay.portal.search.elasticsearch.internal.ElasticsearchEngineConfigurator.initialize(ElasticsearchEngineConfigurator.java:89)\n\tat com.liferay.portal.kernel.search.AbstractSearchEngineConfigurator$1.dependenciesFulfilled(AbstractSearchEngineConfigurator.java:75)\n\tat com.liferay.registry.dependency.ServiceDependencyManager.verifyDependencies(ServiceDependencyManager.java:146)\n\tat com.liferay.registry.dependency.ServiceDependencyManager$ServiceDependencyServiceTrackerCustomizer.addingService(ServiceDependencyManager.java:242)\n\tat com.liferay.registry.internal.ServiceTrackerCustomizerAdapter.addingService(ServiceTrackerCustomizerAdapter.java:35)\n\tat org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)\n\tat org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:1)\n\tat org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)\n\tat org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183)\n\tat org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318)\n\tat com.liferay.registry.internal.ServiceTrackerWrapper.open(ServiceTrackerWrapper.java:191)\n\tat com.liferay.registry.dependency.ServiceDependency.open(ServiceDependency.java:73)\n\tat com.liferay.registry.dependency.ServiceDependencyManager.registerDependencies(ServiceDependencyManager.java:72)\n\tat com.liferay.portal.kernel.search.AbstractSearchEngineConfigurator.afterPropertiesSet(AbstractSearchEngineConfigurator.java:84)\n\tat com.liferay.portal.search.internal.SearchEngineHelperImpl.addSearchEngineConfigurator(SearchEngineHelperImpl.java:296)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)\n\tat org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)\n\tat org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)\n\tat org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)\n\tat org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:655)\n\tat org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1722)\n\tat org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1699)\n\tat org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:371)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:320)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)\n\tat org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:917)\n\tat org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)\n\tat org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)\n\tat org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1012)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:968)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)\n\tat org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:917)\n\tat org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)\n\tat org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)\n\tat org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1012)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:968)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)\n\tat org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:917)\n\tat org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)\n\tat org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)\n\tat org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1012)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:968)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)\n\tat org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:917)\n\tat org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)\n\tat org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)\n\tat org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)\n\tat org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1012)\n\tat org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:968)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)\n\tat org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)\n\tat org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:917)\n\tat org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)\n\tat org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)\n\tat org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)\n\tat org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)\n\tat com.liferay.portal.bootstrap.ModuleFrameworkImpl._registerService(ModuleFrameworkImpl.java:1222)\n\tat com.liferay.portal.bootstrap.ModuleFrameworkImpl._registerApplicationContext(ModuleFrameworkImpl.java:1188)\n\tat com.liferay.portal.bootstrap.ModuleFrameworkImpl.registerContext(ModuleFrameworkImpl.java:329)\n\tat com.liferay.portal.module.framework.ModuleFrameworkUtilAdapter.registerContext(ModuleFrameworkUtilAdapter.java:71)\n\tat com.liferay.portal.spring.context.PortalContextLoaderListener.contextInitialized(PortalContextLoaderListener.java:352)\n\tat org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4812)\n\tat org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5255)\n\tat org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147)\n\tat org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725)\n\tat org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:701)\n\tat org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717)\n\tat org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:585)\n\tat org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1794)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)","exception_class":"java.lang.ClassNotFoundException","exception_message":"com.github.mustachejava.Mustache cannot be found by com.liferay.portal.search.elasticsearch_2.1.33"},"source_host":"dnebook","method":"configure","level":"DEBUG","message":"[Hardcase] failed to load mustache","mdc":{},"@timestamp":"2019-01-16T23:32:31.547Z","file":"ScriptModule.java","line_number":"83","thread_name":"localhost-startStop-1","@version":1,"logger_name":"org.elasticsearch.script","class":"org.elasticsearch.script.ScriptModule"}
{"@timestamp":"2019-01-16T23:32:32.352Z","source_host":"dnebook","file":"HierarchyCircuitBreakerService.java","method":"","level":"TRACE","line_number":"123","thread_name":"localhost-startStop-1","@version":1,"logger_name":"org.elasticsearch.indices.breaker","message":"[Hardcase] parent circuit breaker with settings [parent,type=PARENT,limit=5347580313\/4.9gb,overhead=1.0]","class":"org.elasticsearch.indices.breaker.HierarchyCircuitBreakerService","mdc":{}}

Pretty printed, the JSON looks like:

{
  "@timestamp": "2019-01-16T23:32:31.248Z",
  "source_host": "dnebook",
  "file": "ThreadPool.java",
  "method": "rebuild",
  "level": "DEBUG",
  "line_number": "552",
  "thread_name": "localhost-startStop-1",
  "@version": 1,
  "logger_name": "org.elasticsearch.threadpool",
  "message": "[Hardcase] creating thread_pool [snapshot], type [scaling], min [1], size [4], keep_alive [5m]",
  "class": "org.elasticsearch.threadpool.ThreadPool",
  "mdc": {}
}
{
  "exception": {
    "stacktrace": "java.lang.ClassNotFoundException: com.github.mustachejava.Mustache cannot be found by com.liferay.portal.search.elasticsearch_2.1.33
	    at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:444)
	    at <snip...>",
    "exception_class": "java.lang.ClassNotFoundException",
    "exception_message": "com.github.mustachejava.Mustache cannot be found by com.liferay.portal.search.elasticsearch_2.1.33"
  },
  "source_host": "dnebook",
  "method": "configure",
  "level": "DEBUG",
  "message": "[Hardcase] failed to load mustache",
  "mdc": {},
  "@timestamp": "2019-01-16T23:32:31.547Z",
  "file": "ScriptModule.java",
  "line_number": "83",
  "thread_name": "localhost-startStop-1",
  "@version": 1,
  "logger_name": "org.elasticsearch.script",
  "class": "org.elasticsearch.script.ScriptModule"
}
{
  "@timestamp": "2019-01-16T23:32:32.352Z",
  "source_host": "dnebook",
  "file": "HierarchyCircuitBreakerService.java",
  "method": "",
  "level": "TRACE",
  "line_number": "123",
  "thread_name": "localhost-startStop-1",
  "@version": 1,
  "logger_name": "org.elasticsearch.indices.breaker",
  "message": "[Hardcase] parent circuit breaker with settings [parent,type=PARENT,limit=5347580313/4.9gb,overhead=1.0]",
  "class": "org.elasticsearch.indices.breaker.HierarchyCircuitBreakerService",
  "mdc": {}
}

Now that we have our JSON logs, our next step is to set up Filebeat...

Filebeat Preparation

We are going to deploy Filebeat to our Liferay app server node(s). As a lightweight log shipper, it will not consume significant resources from the system.

You'll want to download the right version of Filebeat, but choosing the right version starts with knowing what version of Elasticsearch you are going to be using for your log file indexing. The right version can be identified from Elastic's product compatibility matrix found here: https://www.elastic.co/support/matrix#matrix_compatibility.

If you are using Elasticsearch for your Liferay indexing/search needs, you might be tempted to reuse the same server for your log data. Note that by doing so, you will be sharing Elastic resources between the Liferay needs and the log centralization needs. This will affect Elasticsearch's performance when indexing Liferay content and responding to Liferay search queries.

Additionally if the indexing of the log messages trigger an outage of Elastic (i.e. you run out of disk space storing all of the log data), your Liferay site would also not be available.

For these reasons, I often recommend setting up a separate Elasticsearch server/cluster. It is okay to scale back this Elasticsearch environment; after all, logging data is nice to have but is not necessarily mission critical. Slow indexing and searching performance of log data should not be a problem.

Follow the instructions from the download site for Filebeat (including service management to auto-start when the system starts, if available for your platform).

For the filebeat.yml file, we're going to configure it to read from our Liferay logs directory and to go after all of the json files, and we'll output the records to our Logstash server:

filebeat.prospectors:
# Older versions would be filebeat.inputs instead of prospectors.

- type: log
  paths:
    - $LIFERAY_HOME$/logs/liferay*.json.log
  json.keys_under_root: true
  json.add_error_key: true
  json.message_key: message

output.logstash:
  hosts: ["logstash.example.com:5044"]
NOTE: The $LIFERAY_HOME$ is actually a replacement you need to make; the environment variable would not be injected for you.

This configuration will pull in the JSON log messages from the file(s) specified by the Liferay log4j configuration example above. It will process the JSON entry for us and send them all to our Logstash host(s). Be sure to make whatever changes are necessary for your own environment.

Filebeat will not delete the log file(s) after they have been harvested; you'll still want to set up a logrotate task to delete old logs from the filesystem. Since you're pushing the data to Elastic, you should only need to keep around a day or two to ensure they have been processed before deletion.

Logstash Preparation

We're going to opt for a pretty darn simple Logstash configuration:

input {
  beats {
    port => 5044
  }
}

output {
  elasticsearch {
    hosts => ["http://elasticsearch.example.com:9200"]
    index => "liferay-log-%{+YYYY.MM.dd}"
  }
}

This configuration will receive Beats input, in our case Filebeat, on port 5044. We redirect that output to Elasticsearch at the specific host and rotating indexes by day.

Since we're logging in JSON and sending it via Filebeat, we don't need to deal with any codecs in the Logstash configuration.

Kafka Preparation

Most online doco for setting up an ELK stack for centralized logging does not talk about a production-level deployment. They present the ELK components in a simple configuration without discussing how to deal with and manage load generated in a production environment.

When you are centralizing the logging, say, of a 6-node Liferay cluster with each node shipping log messages off to a Logstash instance for storage in Elastic, there's actually a heavy network impact and processing hit on Logstash. The chance of log message dropping and negative performance hit increases. This data loss may not be tolerable for a live monitoring solution.

To take some of the strain off of the process, introducing a streaming or messaging solution can help manage load and prevent loss scenarios. I like Apache Kafka as a solution here, but Redis is another solution as would be RabbitMQ.

If we were injecting Kafka between Filebeat and Logstash, our Filebeat configuration would use the following output:

output.kafka:
  hosts: ["kafka.example.com:9092"]
  topic: LOGS-TOPIC

Using this output, we ship the messages to our Kafka host (for a Kafka cluster, list all hosts) on the named topic. The Logstash input (discussed in the next section) would use the following input:

input {
  kafka {
    bootstrap_servers => 'kafka.example.com:9092'
    topics => ["LOGS-TOPIC"]
    codec => json {}
  }
}

These changes will inject Kafka into the mix and manage some of the load for the Logstash service.

To use Redis or RabbitMQ, refer to the Filebeat and Logstash configuration.

Elasticsearch Preparation

So there's no real preparation for Elasticsearch necessary for our centralized logging solution; I'm just including this section to call out this detail so there is no ambiguity.

Checkpoint

At this point we have configured all of the key components for getting log messages and send them off to Elasticsearch for storage.

Liferay will now generate the JSON log files, Filebeat picks up the logs and ships them to Logstash (optionally leveraging Kafka or another queue mechanism), and Logstash loads the messages into Elasticsearch for indexing.

Next up, we'll look at some Kibana stuff...

Kibana Preparation

Next we'll do some standard Kibana setup to use our new indexes:

First, click on Management, then on Index Pattern so we can add a new pattern. Enter the pattern as "liferay-log-*" as this matches our index pattern in the Logstash configuration. For the Time Filter, use @timestamp to group messages by time.

NOTE: The index pattern you pick should match whatever pattern you define for Logstash.

Next you can click on the Discover panel and check out what has been loaded:

You'll see that your log messages have been loaded into Elasticsearch and you can now start building out your visualizations.

I created a few, nothing fancy:

First one just shows warnings and errors. Second is a pie chart of the various log levels to see what the balance is.

In order to share, here's the visualization scripts for each.

First the log messages:

[
  {
    "_id": "de871ec0-3a2c-11e9-b520-c5127db608e3",
    "_type": "search",
    "_source": {
      "title": "Warnings And Errors",
      "description": "",
      "hits": 0,
      "columns": [
        "level",
        "host",
        "message"
      ],
      "sort": [
        "@timestamp",
        "desc"
      ],
      "version": 1,
      "kibanaSavedObjectMeta": {
        "searchSourceJSON": "{\"index\":\"b57f74d0-3a29-11e9-b520-c5127db608e3\",\"highlightAll\":true,\"version\":true,\"query\":{\"query\":\"level:WARN OR level:ERROR\",\"language\":\"lucene\"},\"filter\":[]}"
      }
    }
  }
]

Next the pie chart:

[
  {
    "_id": "4891c490-3a2e-11e9-b520-c5127db608e3",
    "_type": "visualization",
    "_source": {
      "title": "Log Levels",
      "visState": "{\"title\":\"Log Levels\",\"type\":\"pie\",\"params\":{\"type\":\"pie\",\"addTooltip\":true,\"addLegend\":true,\"legendPosition\":\"right\",\"isDonut\":true,\"labels\":{\"show\":false,\"values\":true,\"last_level\":true,\"truncate\":100}},\"aggs\":[{\"id\":\"1\",\"enabled\":true,\"type\":\"count\",\"schema\":\"metric\",\"params\":{}},{\"id\":\"2\",\"enabled\":true,\"type\":\"terms\",\"schema\":\"segment\",\"params\":{\"field\":\"level.keyword\",\"size\":5,\"order\":\"desc\",\"orderBy\":\"1\",\"otherBucket\":false,\"otherBucketLabel\":\"Other\",\"missingBucket\":false,\"missingBucketLabel\":\"Missing\"}}]}",
      "uiStateJSON": "{}",
      "description": "",
      "version": 1,
      "kibanaSavedObjectMeta": {
        "searchSourceJSON": "{\"index\":\"b57f74d0-3a29-11e9-b520-c5127db608e3\",\"query\":{\"query\":\"\",\"language\":\"lucene\"},\"filter\":[]}"
      }
    }
  }
]

Conclusion

So now we have a working centralized logging platform. We can direct the logs from Liferay nodes to a centralized Elasticsearch service and, through Kibana, we can expose the logs to those that need to see them. All without granting direct server access.

We can set up Kibana dashboard visualizations so we can monitor logs and see things that are occurring before they get reported.

Have some useful visualizations that you use for your logging dashboard? Please share them here, I'm sure I and others would greatly appreciate what you have to offer.

Update #1: I was given a reference to a blog that my Liferay friends from Spain put together that has some great monitoring ideas and suggestions: https://community.liferay.com/blogs/-/blogs/taking-advantage-of-elasticsearch-by-using-elastic-stack-in-order-to-monitorize-liferay-dxp