dcache: alarms: Extend log level capture to all levels; fix server-si…

…de logging

module: dcache, package alarms

Because of issues that were not working with the Turbo Filter, the Alarm definition was implemented to accept only messages at WARN or ERROR levels.  It is preferable to allow an ALARM to be defined against any logging level.

I have retested the Turbo Filter and it is now working as advertised.  This patch

- moves the alarms.remote-logging.level property to the level element of the remote appender in the TurboFilter, where it belongs, and eliminates the extra filter on the appender itself;
- makes the necessary modifications to allow ALARMS to be captured at any level, even though ERROR and WARN will undoubtedly be the most common (and even though to capture those below the WARN level one risks a considerable amount of congestion on the alarm server; in such a case it is advisable not to use the XML store).

The logback-server.xml has also been adjusted so that:

- the log file messages are fuller and resemble the optional MAIL message;
- events from the server's own domain are excluded from the store and the history and are placed in the server.log

Testing:

On testbed.  Tested by varying the levels of alarms.remote-logging.level (set globally in the dcache.conf file) and observing the results in the history.log, server.log and on the webadmin page.  Also added an arbitrary ALARM defined at INFO level and observed it appear on the page when the remote logging level was low enough.

Target: master
Patch: http://rb.dcache.org/r/5522
Require-book: yes
Require-notes: yes
Acked-by: Gerd
Request: 2.6

RELEASE NOTES:
BOOK:

Alarms can now be defined at all logging levels.  However, the volume of traffic sent to the server (where the logging message is captured and converted into a potential alarm) increases dramatically below the WARN level.  If this kind of alarm is desired, it is advisable to run the RDBMS version of the store, as the XML store fills up to scores of pages very quickly and searching becomes slow.  Logging messages from the logging server and the domain in which it runs are not sent to the store, but are written to the server.log.

Conflicts:
	skel/var/alarms/logback-server.xml

modules/dcache/src/main/java/org/dcache/alarms/commandline/SendAlarm.java

@@ -267,6 +267,11 @@ private static Logger configureLogger(String host, String port) throws JoranExce
         lc.reset();
         lc.putProperty("remote.server.host", host);
         lc.putProperty("remote.server.port", port);
+        /*
+         * Allow all levels to be sent.  The remote server will be set
+         * to intercept only messages sent at the defined dcache.log.remote.level.
+         */
+        lc.putProperty("remote.log.level", Level.DEBUG.toString());
 
         JoranConfigurator configurator = new JoranConfigurator();
         configurator.setContext(lc);
@@ -291,7 +296,7 @@ private static void printHelp() {
         }
         message.append(INDENT)
                .append("('dcache send' automatically provides destination uri")
-               .append(" based on alarms.server.host and alarms.server.port)")
+               .append(" based on dcache.log.server.host and dcache.log.server.port)")
                .append(LBRK);
         System.out.println(message);
     }
@@ -306,6 +311,10 @@ private static void sendAlarm(AlarmArguments alarmArgs) throws JoranException {
             logger.error(alarmArgs.marker, alarmArgs.message);
         } else if (Level.WARN.equals(alarmArgs.level)) {
             logger.warn(alarmArgs.marker, alarmArgs.message);
+        } else if (Level.INFO.equals(alarmArgs.level)) {
+            logger.info(alarmArgs.marker, alarmArgs.message);
+        } else if (Level.DEBUG.equals(alarmArgs.level)) {
+            logger.debug(alarmArgs.marker, alarmArgs.message);
         }
     }
 }

modules/dcache/src/main/java/org/dcache/alarms/dao/LogEntry.java

@@ -203,8 +203,7 @@ public void setAlarm(Boolean alarm) {
     public void setAlarmMetadata(ILoggingEvent event, AlarmDefinition definition) {
         Level level = event.getLevel();
         if (definition == null) {
-            setSeverity(level == Level.ERROR ? Severity.HIGH.ordinal()
-                            : Severity.MODERATE.ordinal());
+            setSeverity(getSeverityFromLevel(level).ordinal());
             if (alarm) {
                 setType(event.getMarker().toString());
             } else {
@@ -302,9 +301,18 @@ public void update(LogEntry entry) {
         notes = entry.getNotes();
     }
 
-    private String getFormattedDate(Date date) {
+    private static String getFormattedDate(Date date) {
         DateFormat format = new SimpleDateFormat(FORMAT);
         format.setLenient(false);
         return format.format(date);
     }
+
+    private static Severity getSeverityFromLevel(Level level) {
+        switch(level.toInt()) {
+            case Level.ERROR_INT: return Severity.HIGH;
+            case Level.WARN_INT : return Severity.MODERATE;
+            default:
+                return Severity.LOW;
+        }
+    }
 }

modules/dcache/src/main/java/org/dcache/alarms/logback/LogEntryAppender.java

@@ -60,16 +60,19 @@ LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
 package org.dcache.alarms.logback;
 
 import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.classic.spi.LoggingEvent;
 import ch.qos.logback.classic.spi.ThrowableProxy;
 import ch.qos.logback.core.Appender;
 import ch.qos.logback.core.AppenderBase;
 import ch.qos.logback.core.spi.AppenderAttachable;
+import org.apache.log4j.MDC;
 import org.jdom.Document;
 import org.jdom.Element;
 import org.jdom.JDOMException;
 import org.jdom.input.SAXBuilder;
+import org.slf4j.LoggerFactory;
 import org.slf4j.Marker;
 
 import java.io.File;
@@ -112,6 +115,7 @@ public class LogEntryAppender extends AppenderBase<ILoggingEvent> implements
     private String path;
     private String propertiesPath;
     private String definitionsPath;
+    private String currentDomain;
 
     public void addAlarmType(AlarmDefinition definition) {
         definitions.put(definition.getType(), definition);
@@ -191,6 +195,8 @@ public void setUser(String user) {
     @Override
     public void start() {
         try {
+            currentDomain = String.valueOf(MDC.get(IAlarms.DOMAIN));
+
             if (definitionsPath != null && definitionsPath.trim().length() > 0) {
                 File file = new File(definitionsPath);
                 if (!file.exists()) {
@@ -228,10 +234,23 @@ public void start() {
     protected void append(ILoggingEvent eventObject) {
         try {
             if (isStarted()) {
+                if (currentDomain.equals(eventObject.getMDCPropertyMap()
+                                                    .get(IAlarms.DOMAIN_TAG))) {
+                    Logger logger = (Logger)LoggerFactory.getLogger("domain");
+                    if (logger != null &&
+                                    logger.isEnabledFor(eventObject.getLevel())) {
+                        logger.callAppenders(eventObject);
+                    }
+                    return;
+                }
+
                 LogEntry entry = createEntryFromEvent(eventObject);
                 String type = entry.getType();
                 if (type != null && !Level.ERROR.toString().equals(type)
-                                && !Level.WARN.toString().equals(type)) {
+                                 && !Level.WARN.toString().equals(type)
+                                 && !Level.INFO.toString().equals(type)
+                                 && !Level.DEBUG.toString().equals(type)
+                                 && !Level.TRACE.toString().equals(type)) {
                     /*
                      * means it was possibly not sent with an ALARM marker; add
                      * one so any delegated appender with an ALARM marker filter

modules/dcache/src/main/java/org/dcache/alarms/server/LogEntryServerWrapper.java

@@ -95,6 +95,7 @@ public class LogEntryServerWrapper {
     private String url;
     private String user;
     private String pass;
+    private String level;
     private Integer port;
 
     private SimpleSocketServer server;
@@ -115,6 +116,10 @@ public void setDriver(String driver) {
         this.driver = driver;
     }
 
+    public void setLevel(String level) {
+        this.level = level;
+    }
+
     public void setPass(String pass) {
         this.pass = pass;
     }
@@ -165,6 +170,7 @@ public void startUp() throws JoranException {
         loggerContext.putProperty("alarms.store.db.pass", pass);
         loggerContext.putProperty("alarms.store.db.properties", properties);
         loggerContext.putProperty("alarms.definitions.path", definitionsPath);
+        loggerContext.putProperty("alarms.server.log.level", level);
 
         JoranConfigurator configurator = new JoranConfigurator();
         configurator.setContext(loggerContext);

modules/dcache/src/main/resources/org/dcache/alarms/commandline/logback.xml

@@ -14,7 +14,7 @@
     <root level="off">
     </root>
 
-    <logger name="Commandline" level="warn" additivity="false">
+    <logger name="Commandline" level="${remote.log.level}" additivity="false">
         <appender-ref ref="stdout"/>
         <appender-ref ref="remote"/>
     </logger>

modules/dcache/src/main/resources/org/dcache/alarms/server/alarms.xml

@@ -16,7 +16,7 @@
 
     <bean id="server" class="org.dcache.alarms.server.LogEntryServerWrapper"
         init-method="startUp" destroy-method="shutDown">
-        <property name="port" value="${alarms.server.port}"/>
+        <property name="port" value="${dcache.log.server.port}"/>
         <property name="baseDir" value="${alarms.dir}"/>
         <property name="configFile" value="${alarms.server.config}"/>
         <property name="path" value="${alarms.store.path}"/>
@@ -26,6 +26,7 @@
         <property name="pass" value="${alarms.store.db.pass}"/>
         <property name="properties" value="${alarms.store.db.properties}"/>
         <property name="definitions" value="${alarms.definitions.path}"/>
+        <property name="level" value="${alarms.server.log.level}"/>
     </bean>
 
     <beans profile="rdbms">

skel/etc/logback.xml

@@ -90,13 +90,10 @@
 
   <!-- sends error/warn to a remote logback server -->
   <appender name="remote" class="ch.qos.logback.classic.net.SocketAppender">
-      <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-          <level>${alarms.remote-logging.level}</level>
-      </filter>
       <!-- adds a few properties to MDC -->
       <filter class="org.dcache.alarms.logback.RemoteMDCFilter"/>
-      <remoteHost>${alarms.server.host}</remoteHost>
-      <port>${alarms.server.port}</port>
+      <remoteHost>${dcache.log.server.host}</remoteHost>
+      <port>${dcache.log.server.port}</port>
       <reconnectionDelay>10000</reconnectionDelay>
   </appender>
 

skel/man/man8/dcache.8

@@ -287,8 +287,8 @@ given, it defaults to "NA"; if service is not given, it defaults to
 
 .TP.TP
 .B log level
-can be ERROR (default) or WARN; these translate into HIGH and MODERATE
-severity levels.
+can be ERROR (default), WARN, INFO, DEBUG; these translate into HIGH, MODERATE,
+LOW and LOW severity levels.
 
 .TP.TP
 .B alarm type

skel/share/defaults/alarms.properties

@@ -9,19 +9,6 @@
 #
 alarms/cell.name=alarms
 
-#  ---- Level of events to send via the socket appender to the remote server
-#
-(one-of?off|error|warn)alarms.remote-logging.level=error
-
-#  ---- Host on which the alarm server will run
-#       relative to this dCache installation
-#
-alarms.server.host=localhost
-
-#  ---- Port on which the alarm server will listen
-#
-alarms.server.port=60001
-
 #  ---- Main alarms area
 #
 alarms.dir=@dcache.paths.alarms@
@@ -30,6 +17,10 @@ alarms.dir=@dcache.paths.alarms@
 #
 alarms.server.config=${alarms.dir}/logback-server.xml
 
+#  ---- Server root log level.
+#
+(one-of?off|error|warn|info|debug)alarms.server.log.level=warn
+
 #  ---- Server side custom alarm definitions
 #
 #      Definitions can be added to this file; it is referenced by the

skel/share/defaults/dcache.properties

@@ -74,6 +74,15 @@
 (not-for-services)dcache.log.level.remote=warn
 (not-for-services)dcache.log.level.events=off
 
+# Host on which the remote log server will run
+# relative to this dCache installation
+#
+(not-for-services)dcache.log.server.host=localhost
+
+# Port on which the remote log server will listen
+#
+(not-for-services)dcache.log.server.port=60001
+
 # Log formats
 #
 # These define the log format of various log output targets. For details on the format visit

skel/share/lib/alarm.sh

@@ -6,8 +6,8 @@ send_alarm() # $@ = [-s=<source-uri>] [-l=<log level>] [-t=<alarm subtype>] mess
     local host
     local port
 
-    host=$(getProperty alarms.server.host)
-    port=$(getProperty alarms.server.port)
+    host=$(getProperty dcache.log.server.host)
+    port=$(getProperty dcache.log.server.port)
 
     CLASSPATH="$(getProperty dcache.paths.classpath)" quickJava org.dcache.alarms.commandline.SendAlarm -d="dst://${host}:${port}" "$@"
 }

skel/share/services/alarms.batch

@@ -4,7 +4,7 @@
 
 onerror shutdown
 
-check -strong alarms.server.port
+check -strong dcache.log.server.port
 check -strong alarms.server.config
 check -strong alarms.store.db.type
 
@@ -23,7 +23,7 @@ define env startService.exe enddefine
   create org.dcache.cells.UniversalSpringCell ${cell.name} \
         "classpath:org/dcache/alarms/server/alarms.xml \
         -profiles=${alarms.store.db.type} \
-        -alarms.server.port=${alarms.server.port} \
+        -dcache.log.server.port=${dcache.log.server.port} \
         -alarms.dir=${alarms.dir} \
         -alarms.server.config=${alarms.server.config} \
         -alarms.store.path=${alarms.store.path} \
@@ -36,7 +36,8 @@ define env startService.exe enddefine
         -alarms.store.db.host=${alarms.store.db.host} \
         -alarms.store.db.user=${alarms.store.db.user} \
         -alarms.store.db.pass=${alarms.store.db.pass} \
-        -alarms.store.db.properties=${alarms.store.db.properties}"
+        -alarms.store.db.properties=${alarms.store.db.properties} \
+        -alarms.server.log.level=${alarms.server.log.level}"
 enddefine
 
 onerror continue

skel/var/alarms/logback-server.xml

@@ -1,7 +1,7 @@
 <?xml version="1.0" encoding="UTF-8" ?>
 
 <configuration>
-    <appender name="LOGBACK" class="ch.qos.logback.core.rolling.RollingFileAppender">
+    <appender name="SERVER" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <File>${alarms.dir}/server.log</File>
 
         <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
@@ -15,7 +15,7 @@
         </triggeringPolicy>
 
         <layout class="ch.qos.logback.classic.PatternLayout">
-            <Pattern>%relative %-5level %logger - %message%n</Pattern>
+            <Pattern>%d{dd MMM yyyy HH:mm:ss} %-5level %logger - %message%n</Pattern>
         </layout>
     </appender>
 
@@ -33,7 +33,7 @@
         </triggeringPolicy>
 
         <encoder>
-            <pattern>%d{dd MMM yyyy HH:mm:ss} %m%n</pattern>
+            <pattern>%-5level %d{dd MMM yyyy HH:mm:ss} \(%X{host}\)\(%X{cells.cell}\)\(%X{cells.domain}\) %m%n</pattern>
         </encoder>
     </appender>
 
@@ -52,7 +52,7 @@
         <from></from>
         <subject>dCache Alarm</subject>
         <layout class="ch.qos.logback.classic.PatternLayout">
-            <pattern>%d{dd MMM yyyy HH:mm:ss} \(%X{cells.cell}\) [%X{org.dcache.ndc}] %m%n</pattern>
+            <pattern>%-5level %d{dd MMM yyyy HH:mm:ss} \(%X{host}\)\(%X{cells.cell}\)\(%X{cells.domain}\) %m%n</pattern>
         </layout>
         <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTrackerImpl">
             <!-- send just one log entry per email -->
@@ -82,11 +82,16 @@
         <!-- <appender-ref ref="ALARM_MAIL"/> -->
     </appender>
 
-     <logger name="ch.qos.logback" additivity="false">
-         <appender-ref ref="LOGBACK"/>
+    <logger name="ch.qos.logback" additivity="false" level="warn">
+         <appender-ref ref="SERVER"/>
     </logger>
 
-    <root level="warn">
+    <!-- do not change the name of this logger (used internally) -->
+    <logger name="domain" additivity="false">
+         <appender-ref ref="SERVER"/>
+    </logger>
+
+    <root level="${alarms.server.log.level}">
         <appender-ref ref="STORE"/>
     </root>
-</configuration>
+</configuration>