Unable to get c3p0 logging to go to file

Question

I am using Java 8, Hibernate 4.3.11 and c3p0 9.2.1 and the standard Java logging package and am having trouble with writing the debug information from c3p0 to my debug log.

I added

 -Dcom.mchange.v2.log.MLog=com.mchange.v2.log.jdk14logging.Jdk14MLog

to start up, and this gets c3p0 to use standard logging and write to the console , but it doesnt write to my debug log file.

I initialize loggers for my application and lib

SongKong.ioLogger = Logger.getLogger("org.jaudiotagger");
MainWindow.logger = Logger.getLogger("com.jthink");

and then call my LogProperties class to configure the logs files and console and writing the data, and this works.

What am I doing wrong

  package com.jthink.songkong.logging;


    import com.jthink.songkong.cmdline.SongKong;
    import com.jthink.songkong.preferences.GeneralPreferences;
    import com.jthink.songkong.preferences.UserPreferences;
    import com.jthink.songkong.ui.MainWindow;
    import com.jthink.songkong.util.Platform;

    import java.io.IOException;
    import java.nio.charset.StandardCharsets;
    import java.util.logging.ConsoleHandler;
    import java.util.logging.FileHandler;
    import java.util.logging.Level;
    import java.util.logging.Logger;

    /**
     * This defines the command line properties of SongKong, currently consists of logger settings
     */
    public final class LogProperties
    {

        public static int LOG_SIZE_IN_BYTES = 10000000;

        public LogProperties()
        {
            try
            {

                //Set logging for jaudiotagger lib, user configurable
                SongKong.ioLogger.setLevel(Level.parse(String.valueOf(GeneralPreferences.getInstance().getIoDebugLevel())));
                SongKong.ioLogger.setUseParentHandlers(false);

                //Set logging for songkongdebug, user configurable
                MainWindow.logger.setLevel(Level.parse(String.valueOf(GeneralPreferences.getInstance().getDebugLevel())));
                MainWindow.logger.setUseParentHandlers(false);

                //C3p0 Logger
                Logger c3p0Logger = Logger.getLogger("com.mchange.v2.c3p0");
                c3p0Logger.setLevel(Level.FINEST);
                c3p0Logger.setUseParentHandlers(false);

                //Set Filehandler used for writing to debug log
                String logFileName = Platform.getPlatformLogFolderInLogfileFormat() + "songkong_debug%u-%g.log";
                FileHandler fe = new FileHandler(logFileName, LOG_SIZE_IN_BYTES, 10, true);
                fe.setEncoding(StandardCharsets.UTF_8.name());
                fe.setFormatter(new com.jthink.songkong.logging.LogFormatter());
                fe.setLevel(Level.FINEST);

                //Write output from these loggers to the debug log file
                MainWindow.logger.addHandler(fe);
                SongKong.ioLogger.addHandler(fe);
                c3p0Logger.addHandler(fe);

                ConsoleHandler ch = new ConsoleHandler();
                ch.setFormatter(new com.jthink.songkong.logging.LogFormatter());
                ch.setLevel(Level.FINEST);
                MainWindow.logger.addHandler(ch);
                SongKong.ioLogger.addHandler(ch);
                c3p0Logger.addHandler(ch);
            }
            catch (IOException ioe)
            {
                MainWindow.userInfoLogger.severe("Unable to open log file");
            }
        }

    }

I need the debugging to get written to the log file because I want a customer to run some tests, so it is no good to be if the data is just written to console. Also the format of c3p0 data written the console is not in the format of my other messages (as defined by com.jthink.songkong.logging.LogFormatter()) so it seems that my call to LogProperties() is effectively being ignored even though it is called before I access c3p0 for the first time.

e.g this is output to console at startup

debuglogfile is:C:\Users\Paul\AppData\Roaming\SongKong\Logs/songkong_debug%u-%g.log
userlogfile is:C:\Users\Paul\AppData\Roaming\SongKong\Logs/songkong_user%u-%g.log
23/08/2019 10.44.26:BST:SongKong:setLocale:SEVERE: Locale is:en
23/08/2019 10.44.27:BST:SongKong:setFonts:WARNING: Fonts Enabled:true
23/08/2019 10.44.27:BST:SongKong:setFonts:WARNING: Fonts configured successfully
23/08/2019 10.44.27:BST:SongKong:init:WARNING: end
23/08/2019 10.44.27:BST:SongKong:finish:WARNING: finish
23/08/2019 10.44.29:BST:SongKong:writeSystemInfo:WARNING: SongKong 6.3 Psychocandy 1099 24/07/2019 using Java 1.8.0_181 25.181-b13 64bit on Windows 10 10.0 amd64 initialized successfully
23/08/2019 10.44.29:BST:SongKong:writeSystemInfo:WARNING: No of CPUs:8
23/08/2019 10.44.29:BST:SongKong:writeSystemInfo:WARNING: SongKong has been configured with minimum heap memory of 100 mb, maximum heap memory of 1,778 mb and maximum permanent memory of -32 mb
23/08/2019 10.44.29:BST:SongKong:writeSystemInfo:WARNING: Total Computer Memory is 24,466 mb
23/08/2019 10.44.30:BST:SongKong:writeSystemInfo:WARNING: Username:Paul:Domain:pclaptop:RunningAsAdmin:false
23/08/2019 10.44.30:BST:SongKong:checkDatabase:WARNING: Setting Db Folder:C:\Users\Paul\AppData\Roaming\SongKong/Database
23/08/2019 10.44.30:BST:SongKong:checkDatabase:WARNING: Lock File remaining from previous, deleting lock
23/08/2019 10.44.30:BST:HibernateUtil:createFactory:SEVERE: ----Initilizing Hibernate Session factory
Aug 23, 2019 10:44:31 AM com.mchange.v2.log.MLog <clinit>
INFO: MLog clients using java 1.4+ standard logging.
Aug 23, 2019 10:44:32 AM com.mchange.v2.c3p0.C3P0Registry banner
INFO: Initializing c3p0-0.9.2.1 [built 20-March-2013 10:47:27 +0000; debug? true; trace: 10]
Aug 23, 2019 10:44:32 AM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@3c73cbbb [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@adb66302 [ acquireIncrement -> 3, acquireRetryAttempts -> 10, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> true, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 2rwcn5a41gohnzr1p7tndj|54e1c68b, idleConnectionTestPeriod -> 3000, initialPoolSize -> 1, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 2000, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 5, maxStatements -> 3000, maxStatementsPerConnection -> 50, minPoolSize -> 1, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@2d7c4b75 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> 2rwcn5a41gohnzr1p7tndj|f736069, jdbcUrl -> jdbc:h2:async:C:\Users\Paul\AppData\Roaming\SongKong/Database/Database;FILE_LOCK=SOCKET;MVCC=TRUE;DB_CLOSE_ON_EXIT=FALSE;CACHE_SIZE=50000;, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 10, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> 2rwcn5a41gohnzr1p7tndj|a38c7fe, numHelperThreads -> 3 ]
23/08/2019 10.44.36:BST:SongKong:checkDatabase:SEVERE: Accessed Database okay
23/08/2019 10.44.36:BST:SongKong:checkCache:WARNING: Checking Cache:C:\Users\Paul\AppData\Roaming\SongKong\Database\EhCache
23/08/2019 10.44.38:BST:SongKong:checkCache:WARNING: Checked Cache:C:\Users\Paul\AppData\Roaming\SongKong\Database\EhCache
23/08/2019 10.44.39:BST:SongKong:setUserAgent:WARNING: start
23/08/2019 10.44.41:BST:AbstractAcoustidQuery:performBasicSubmissionQuery:SEVERE: Posting to url:http://api.acoustid.org/v2/user/lookup?format=xml&client=8XaBELgH&user=7st7qtJpzr
23/08/2019 10.44.42:BST:SongKong:setUserAgent:WARNING: end
23/08/2019 10.44.42:BST:SongKong:finish:WARNING: finish

score 0 · Answer 1 · answered Aug 23 '19 at 14:38

Also the format of c3p0 data written the console is not in the format of my other messages (as defined by com.jthink.songkong.logging.LogFormatter()) so it seems that my call to LogProperties() is effectively being ignored even though it is called before I access c3p0 for the first time.

Loggers are subject to garbage collection. One bug in your code is the following: Logger c3p0Logger = Logger.getLogger("com.mchange.v2.c3p0");

Remove that line and create a constant:

private static final Logger c3p0Logger = Logger.getLogger("com.mchange.v2.c3p0");

score 0 · Accepted Answer · answered Aug 24 '19 at 07:08

The fundamental flaw with my approach was that I was calling my logging code from within the application itself. But what I needed to was specify the following property

java.util.logging.config.class

at startup with the name of my logging config class

e.g

-Djava.util.logging.config.class=com.jthink.songkong.logging.LogProperties

I also needed

-Dcom.mchange.v2.log.MLog=com.mchange.v2.log.jdk14logging.Jdk14MLog

so that c3p0 knew i was using standard logging.

This solved the issue, although not being able to call the class from the code made some logic problematic.

Unable to get c3p0 logging to go to file

2 Answers2