QPID-6239 : [Java Broker] redirect embedded database error logs to common broker log file

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk@1640841 13f79535-47bb-0310-9956-ffa450edef68

4 files changed, 237 insertions, 3 deletions

diff --git a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/StandardEnvironmentFacade.java b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/StandardEnvironmentFacade.java
index b95891d575..f3a06db89c 100644
--- a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/StandardEnvironmentFacade.java
+++ b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/StandardEnvironmentFacade.java
@@ -39,6 +39,7 @@ import org.apache.log4j.Logger;
 
 import org.apache.qpid.server.store.StoreException;
 import org.apache.qpid.server.store.StoreFuture;
+import org.apache.qpid.server.store.berkeleydb.logging.Log4jLoggingHandler;
 
 public class StandardEnvironmentFacade implements EnvironmentFacade
 {
@@ -76,6 +77,10 @@ public class StandardEnvironmentFacade implements EnvironmentFacade
         envConfig.setAllowCreate(true);
         envConfig.setTransactional(true);
 
+        envConfig.setConfigParam(EnvironmentConfig.FILE_LOGGING_LEVEL, "OFF");
+        envConfig.setConfigParam(EnvironmentConfig.CONSOLE_LOGGING_LEVEL, "OFF");
+        envConfig.setLoggingHandler(new Log4jLoggingHandler("["+configuration.getName()+"]"));
+
         Map<String, String> params = new HashMap<>(EnvironmentFacade.ENVCONFIG_DEFAULTS);
         params.putAll(configuration.getParameters());
 
@@ -95,6 +100,7 @@ public class StandardEnvironmentFacade implements EnvironmentFacade
         envConfig.setExceptionListener(new LoggingAsyncExceptionListener());
 
         EnvHomeRegistry.getInstance().registerHome(_environmentPath);
+
         boolean success = false;
         try
         {
diff --git a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/logging/Log4jLoggingHandler.java b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/logging/Log4jLoggingHandler.java
new file mode 100644
index 0000000000..0aec43e4ad
--- /dev/null
+++ b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/logging/Log4jLoggingHandler.java
@@ -0,0 +1,139 @@
+/*
+ *
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ *
+ */
+package org.apache.qpid.server.store.berkeleydb.logging;
+
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.logging.ErrorManager;
+import java.util.logging.Formatter;
+import java.util.logging.Handler;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+
+
+public class Log4jLoggingHandler extends Handler
+{
+    public Log4jLoggingHandler(final String prefix)
+    {
+        setFormatter(new Formatter()
+        {
+            @Override
+            public String format(final LogRecord record)
+            {
+                return prefix + " " + formatMessage(record);
+            }
+        });
+    }
+
+    private static final Map<Level, org.apache.log4j.Level> LEVEL_MAP;
+    static
+    {
+        Map<Level, org.apache.log4j.Level> map = new HashMap<>();
+        map.put(Level.SEVERE, org.apache.log4j.Level.ERROR);
+        map.put(Level.WARNING, org.apache.log4j.Level.WARN);
+        //Note that INFO comes out at DEBUG level as the BDB logging at INFO seems to be more of a DEBUG nature
+        map.put(Level.INFO, org.apache.log4j.Level.DEBUG);
+        map.put(Level.CONFIG, org.apache.log4j.Level.DEBUG);
+        map.put(Level.FINE, org.apache.log4j.Level.TRACE);
+        map.put(Level.FINER, org.apache.log4j.Level.TRACE);
+        map.put(Level.FINEST, org.apache.log4j.Level.TRACE);
+        map.put(Level.ALL, org.apache.log4j.Level.TRACE);
+
+        LEVEL_MAP = Collections.unmodifiableMap(map);
+    }
+
+    private static final org.apache.log4j.Logger BDB_LOGGER = org.apache.log4j.Logger.getLogger("BDB");
+
+
+    @Override
+    public void publish(final LogRecord record)
+    {
+        org.apache.log4j.Level level = convertLevel(record.getLevel());
+        if (BDB_LOGGER.isEnabledFor(level))
+        {
+
+            Formatter formatter = getFormatter();
+
+            try
+            {
+                String message = formatter.format(record);
+                try
+                {
+                    BDB_LOGGER.log(level, message);
+                }
+                catch (RuntimeException e)
+                {
+                    reportError(null, e, ErrorManager.WRITE_FAILURE);
+                }
+            }
+            catch (RuntimeException e)
+            {
+                reportError(null, e, ErrorManager.FORMAT_FAILURE);
+            }
+        }
+    }
+
+    @Override
+    public boolean isLoggable(final LogRecord record)
+    {
+        return BDB_LOGGER.isEnabledFor(convertLevel(record.getLevel()));
+    }
+
+    private org.apache.log4j.Level convertLevel(final Level level)
+    {
+        //Note that INFO comes out at DEBUG level as the BDB logging at INFO seems to be more of a DEBUG nature
+        org.apache.log4j.Level result = LEVEL_MAP.get(level);
+        if(result == null)
+        {
+            if (level.intValue() >= Level.SEVERE.intValue())
+            {
+                result = org.apache.log4j.Level.ERROR;
+            }
+            else if (level.intValue() >= Level.WARNING.intValue())
+            {
+                result = org.apache.log4j.Level.WARN;
+            }
+            else if (level.intValue() >= Level.CONFIG.intValue())
+            {
+                result = org.apache.log4j.Level.DEBUG;
+            }
+            else
+            {
+                result = org.apache.log4j.Level.TRACE;
+            }
+        }
+
+        return result;
+    }
+
+    @Override
+    public void flush()
+    {
+
+    }
+
+    @Override
+    public void close() throws SecurityException
+    {
+
+    }
+}
diff --git a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/replication/ReplicatedEnvironmentFacade.java b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/replication/ReplicatedEnvironmentFacade.java
index 52a7e28f31..c1c06988a3 100644
--- a/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/replication/ReplicatedEnvironmentFacade.java
+++ b/qpid/java/bdbstore/src/main/java/org/apache/qpid/server/store/berkeleydb/replication/ReplicatedEnvironmentFacade.java
@@ -69,18 +69,19 @@ import com.sleepycat.je.rep.vlsn.VLSNRange;
 import com.sleepycat.je.utilint.PropUtil;
 import com.sleepycat.je.utilint.VLSN;
 import org.apache.log4j.Logger;
-import org.apache.qpid.server.store.StoreException;
-import org.apache.qpid.server.store.berkeleydb.BDBUtils;
-import org.apache.qpid.server.util.ServerScopedRuntimeException;
 import org.codehaus.jackson.map.ObjectMapper;
 
 import org.apache.qpid.server.configuration.IllegalConfigurationException;
+import org.apache.qpid.server.store.StoreException;
 import org.apache.qpid.server.store.StoreFuture;
+import org.apache.qpid.server.store.berkeleydb.BDBUtils;
 import org.apache.qpid.server.store.berkeleydb.CoalescingCommiter;
 import org.apache.qpid.server.store.berkeleydb.EnvHomeRegistry;
 import org.apache.qpid.server.store.berkeleydb.EnvironmentFacade;
+import org.apache.qpid.server.store.berkeleydb.logging.Log4jLoggingHandler;
 import org.apache.qpid.server.util.ConnectionScopedRuntimeException;
 import org.apache.qpid.server.util.DaemonThreadFactory;
+import org.apache.qpid.server.util.ServerScopedRuntimeException;
 
 public class ReplicatedEnvironmentFacade implements EnvironmentFacade, StateChangeListener
 {
@@ -1116,6 +1117,10 @@ public class ReplicatedEnvironmentFacade implements EnvironmentFacade, StateChan
         envConfig.setExceptionListener(new ExceptionListener());
         envConfig.setDurability(_defaultDurability);
 
+        envConfig.setConfigParam(EnvironmentConfig.FILE_LOGGING_LEVEL, "OFF");
+        envConfig.setConfigParam(EnvironmentConfig.CONSOLE_LOGGING_LEVEL, "OFF");
+        envConfig.setLoggingHandler(new Log4jLoggingHandler("[" + _configuration.getName() + "]"));
+
         for (Map.Entry<String, String> configItem : environmentParameters.entrySet())
         {
             if (LOGGER.isInfoEnabled())
diff --git a/qpid/java/broker-plugins/derby-store/src/main/java/org/apache/qpid/server/store/derby/DerbyUtils.java b/qpid/java/broker-plugins/derby-store/src/main/java/org/apache/qpid/server/store/derby/DerbyUtils.java
index df9c48d6f9..41c48ffe15 100644
--- a/qpid/java/broker-plugins/derby-store/src/main/java/org/apache/qpid/server/store/derby/DerbyUtils.java
+++ b/qpid/java/broker-plugins/derby-store/src/main/java/org/apache/qpid/server/store/derby/DerbyUtils.java
@@ -22,6 +22,8 @@ package org.apache.qpid.server.store.derby;
 
 
 import java.io.File;
+import java.io.IOException;
+import java.io.Writer;
 import java.nio.charset.Charset;
 import java.sql.Blob;
 import java.sql.Connection;
@@ -31,6 +33,9 @@ import java.sql.PreparedStatement;
 import java.sql.ResultSet;
 import java.sql.SQLException;
 
+import org.apache.log4j.Level;
+import org.apache.log4j.Logger;
+
 import org.apache.qpid.server.store.StoreException;
 
 public class DerbyUtils
@@ -41,11 +46,18 @@ public class DerbyUtils
     private static final String TABLE_EXISTENCE_QUERY = "SELECT 1 FROM SYS.SYSTABLES WHERE TABLENAME = ?";
     private static final Charset UTF8_CHARSET = Charset.forName("UTF-8");
 
+    private static final Logger DERBY_LOG = Logger.getLogger("DERBY");
+    public static final DerbyLogWriter DERBY_LOG_WRITER = new DerbyLogWriter();
+    public static final String DERBY_STREAM_ERROR_METHOD = "derby.stream.error.method";
 
     public static void loadDerbyDriver()
     {
         try
         {
+            // set the error log output
+            System.setProperty(DERBY_STREAM_ERROR_METHOD,
+                               "org.apache.qpid.server.store.derby.DerbyUtils.getDerbyLogWriter");
+
             Class<Driver> driverClass = (Class<Driver>) Class.forName(SQL_DRIVER_NAME);
         }
         catch (ClassNotFoundException e)
@@ -54,6 +66,11 @@ public class DerbyUtils
         }
     }
 
+    public static Writer getDerbyLogWriter()
+    {
+        return DERBY_LOG_WRITER;
+    }
+
     public static String createConnectionUrl(final String name, final String databasePath)
     {
         // Derby wont use an existing directory, so we append parent name
@@ -145,5 +162,72 @@ public class DerbyUtils
     }
 
 
+    private static class DerbyLogWriter extends Writer
+    {
+
+        public static final String DERBY_STARTUP_MESSAGE = "Booting Derby version ";
+        public static final String DERBY_SHUTDOWN_MESSAGE = "Shutting down instance ";
+        public static final String DERBY_CLASS_LOADER_STARTED_MESSAGE = "Database Class Loader started";
+        public static final String DERBY_SYSTEM_HOME = "derby.system.home";
+        public static final String DASHED_LINE = "\\s*-*\\s*";
+
+        private final ThreadLocal<StringBuilder> _threadLocalBuffer = new ThreadLocal<StringBuilder>()
+        {
+            @Override
+            protected StringBuilder initialValue()
+            {
+                return new StringBuilder();
+            }
+        };
+
+        @Override
+        public void write(final char[] cbuf, final int off, final int len) throws IOException
+        {
+            _threadLocalBuffer.get().append(cbuf, off, len);
+        }
+
+        @Override
+        public void flush() throws IOException
+        {
+            String logMessage = _threadLocalBuffer.get().toString();
+            if(!logMessage.matches(DASHED_LINE))
+            {
+                if(logMessage.contains(DERBY_STARTUP_MESSAGE))
+                {
+                    // the first line of the message containing the startup message is the current date/time, which
+                    // we can remove
+                    logMessage = logMessage.substring(logMessage.indexOf('\n') + 1);
+                }
+
+                // This is pretty hideous, but since the Derby logging doesn't have any way of informing us of priority
+                // we simply have to assume everything is a warning except known startup / shutdown messages
+                // which we match using known prefixes.
+
+                Level logLevel = Level.WARN;
+
+                if(logMessage.startsWith(DERBY_STARTUP_MESSAGE)
+                   || logMessage.startsWith(DERBY_SHUTDOWN_MESSAGE))
+                {
+                    logLevel = Level.INFO;
+                }
+                else if(logMessage.startsWith(DERBY_SYSTEM_HOME)
+                   || logMessage.startsWith(DERBY_STREAM_ERROR_METHOD)
+                   || logMessage.startsWith("java.vendor")
+                   || logMessage.startsWith(DERBY_CLASS_LOADER_STARTED_MESSAGE))
+                {
+                    logLevel = Level.DEBUG;
+                }
+
+                DERBY_LOG.log(logLevel, logMessage);
+            }
+            _threadLocalBuffer.set(new StringBuilder());
+        }
+
+        @Override
+        public void close() throws IOException
+        {
+
+        }
+    }
 }