Controlled Logging for Apache-commons-net lib (Jav

Question

I have a very small Java program that is capable of performing FTP over SSL (not SFTP) or FTPS, using apache-commons-net library. The reason why I wrote this program is the client machine is AIX 5.3 which does not support FTP over SSL (OOTB), and the FTP host machine runs FileZilla server with only FTP over SSL enabled. The program runs great without any problem but the amount of logging it generates is huge. My question is- Is there a way to control the amount of logging?

(Note Again- The program works absolutely fine for my minimalist requirement)

Below is a snippet from my code

import java.io.*;
import java.text.MessageFormat;
import java.util.logging.Logger;
import org.apache.commons.
.....
....
....
try {
            int reply;
            logger.info("# Invoking Trust Manager");
            client.setTrustManager(TrustManagerUtils.getAcceptAllTrustManager());
            //client.setTrustManager(TrustManagerUtils.getValidateServerCertificateTrustManager());
            logger.info("# Connect Call");
            client.connect(server, port);
            client.login(username, password);
            logger.info("# Login Success");

            client.setFileType(FTP.ASCII_FILE_TYPE);
            client.execPBSZ(0); // Set protection buffer size
            client.execPROT("P"); // Set data channel protection to private
            client.enterLocalPassiveMode();

            logger.info(MessageFormat.format("Connected to {0} .", server));
            reply = client.getReplyCode();
            if (!FTPReply.isPositiveCompletion(reply)) {
                client.disconnect();
                logger.severe("FTP server refused connection.");
                System.exit(1);
            }

            if (flag.equals("-d")) { //Dir mode
                if (args.length == 7){
                    renameFile = args[6]; //copy rename token
                }
                //We will get the file listing and stream the output to create files
                logger.info("# Invoked Directory mode");
                client.changeWorkingDirectory(remoteFile);
                FTPFile[] ftpFiles;
                ftpFiles = client.listFiles(remoteFile);
                if (ftpFiles != null && ftpFiles.length > 0) {                    
                    for (FTPFile file : ftpFiles) {
                        if (!file.isFile()) {
                            continue;
                        }                        
                        InputStream fin = client.retrieveFileStream(remoteFile + "/" + file.getName());
                        if (fin == null) {
                            logger.severe(MessageFormat.format("could not retrieve file: {0}", file.getName()));
                            continue;
                        }
                        // write the inputStream to a FileOutputStream
                        OutputStream out = new FileOutputStream(new File(localFile + "/"+ renameFile + file.getName()));
                        int read = 0;
                        byte[] bytes = new byte[1024];

                        while ((read = fin.read(bytes)) != -1) {
                            out.write(bytes, 0, read);
                        }
                        fin.close();
                        out.flush();
                        out.close();
                        fin = null;
                        client.completePendingCommand();
                    }
                }
            }

            if (flag.equals("-f")) { //File mode
                //Transfer a single file
                logger.info("# Invoked File mode");
                client.listFiles();
                boolean retrieved = client.retrieveFile(remoteFile, new FileOutputStream(localFile));

                if (retrieved) {
                    logger.info("# File copied.");
                }
            }
        } catch (Exception e) {
            if (client.isConnected()) {
                try {
                    client.disconnect();
                } catch (IOException ex) {
                    ex.printStackTrace();
                }
            }
            logger.severe("!! Could not connect to server.!! Please retry!");
            e.printStackTrace();            
        } finally {
            client.disconnect();            
            logger.info("# FTP Client disconnected");
            System.exit(0);
        }

The log it generates to transfer one file is like below-

Jul 20, 2012 5:00:08 AM com.mff.ftps.FTPSSLTool main
INFO: Connecting to IP: 216.153.173.246 on Port: 00890
Jul 20, 2012 5:00:09 AM com.mff.ftps.FTPSSLTool main
INFO: # Initiating SSL connection
Jul 20, 2012 5:00:09 AM com.mff.ftps.FTPSSLTool main
INFO: # Invoking Trust Manager
Jul 20, 2012 5:00:09 AM com.mff.ftps.FTPSSLTool main
INFO: # Connect Call
IBMJSSEProvider2 Build-Level: -20110513
keyStore is: /usr/java6_64/jre/lib/security/cacerts
keyStore type is: jks
keyStore provider is: 
init keystore
SSLContextImpl:  Using X509ExtendedKeyManager com.ibm.jsse2.xc
SSLContextImpl:  Using X509TrustManager org.apache.commons.net.util.TrustManagerUtils$TrustManager
Installed Providers = 
    IBMJSSE2
    IBMJCE
    IBMJGSSProvider
    IBMCertPath
    IBMSASL
    IBMXMLCRYPTO
    IBMXMLEnc
    Policy
    IBMSPNEGO
JsseJCE:  Using SecureRandom  from provider IBMJCE version 1.2
trigger seeding of SecureRandom
done seeding SecureRandom
IBMJSSE2 to send SCSV Cipher Suite on initial ClientHello
JsseJCE:  Using cipher AES/CBC/NoPadding from provider TBD via init 
IBMJSSE2 will allow RFC 5746 renegotiation per com.ibm.jsse2.renegotiate set to none or default
IBMJSSE2 will not require renegotiation indicator during initial handshake per com.ibm.jsse2.renegotiation.indicator set to OPTIONAL or default taken
IBMJSSE2 will not perform identity checking against the peer cert check during renegotiation per com.ibm.jsse2.renegotiation.peer.cert.check set to OFF or default
JsseJCE:  Using MessageDigest MD5 from provider IBMJCE version 1.2
JsseJCE:  Using MessageDigest SHA from provider IBMJCE version 1.2
JsseJCE:  Using MessageDigest MD5 from provider IBMJCE version 1.2
JsseJCE:  Using MessageDigest SHA from provider IBMJCE version 1.2
%% No cached client session
*** ClientHello, SSLv3
RandomCookie:  GMT: 1342778411 bytes = { 246, 135, 47, 123, 204, 170, 94, 224, 76, 244, 28, 242, 63, 243, 124, 13, 93, 156, 170, 88, 91, 79, 89, 55, 157, 135, 214, 250 }
Session ID:  {}
Cipher Suites: [SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, SSL_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_RC4_128_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_RSA_FIPS_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, SSL_RENEGO_PROTECTION_REQUEST]
Compression Methods:  { 0 }
***
main, WRITE: SSLv3 Handshake, length = 81
main, READ: SSLv3 Handshake, length = 74
*** ServerHello, SSLv3
RandomCookie:  GMT: 1342778410 bytes = { 142, 39, 57, 18, 38, 123, 184, 245, 24, 29, 238, 158, 68, 17, 226, 210, 53, 31, 36, 225, 52, 166, 78, 116, 251, 98, 122, 4 }
Session ID:  {143, 221, 201, 170, 184, 190, 241, 94, 223, 253, 199, 199, 50, 161, 233, 224, 88, 78, 82, 162, 13, 222, 236, 56, 215, 253, 101, 12, 39, 45, 126, 203}
Cipher Suite: SSL_RSA_WITH_RC4_128_MD5
Compression Method: 0
***
Server did not supply RI Extension - com.ibm.jsse2.extended.renegotiation.indicator=optional or default - processing will continue
%% Created:  [Session-1, SSL_RSA_WITH_RC4_128_MD5]
** SSL_RSA_WITH_RC4_128_MD5
main, READ: SSLv3 Handshake, length = 1361
*** Certificate chain
chain [0] = [
[
  Version: V3
  Subject: CN=ftps.thillsecure.com, OU=Terms of use at www.verisign.com/rpa (c)05, OU=Thill Logistics, O=TCFC LLC, L=Neenah, ST=Wisconsin, C=US
  Signature Algorithm: SHA1withRSA, OID = 1.2.840.113549.1.1.5

  Key:  IBMJCE RSA Public Key:
modulus:134055911103149706293270567805752446004906288958857850
public exponent:
65537

  Validity: [From: Sun Dec 04 18:00:00 CST 2011,
               To: Wed Dec 12 17:59:59 CST 2012]
  Issuer: CN=VeriSign Class 3 Secure Server CA - G3, OU=Terms of use at https://www.verisign.com/rpa (c)10, OU=VeriSign Trust Network, O="VeriSign, Inc.", C=US
  SerialNumber: [168622087069244624687861365106323602194]
....
....
....
Hundreds and hundreds of more lines

I am using java.utils.logging.Logger for my own logging purpose, but the lines of logs are getting obfuscated by the numerous lines of log being generated by the apache-commons-net library methods itself.

So again- The question is - "Is there a way to control this logging behavior of the apache-commons-net library itself? Any method I can use or any flag that needs to be set??"

UPDATE:

I finally got to control the logging (Special thanks to Flavio). All I had to do was include System.setProperty("javax.net.debug", "false"); in my code. I had it set initially as System.setProperty("javax.net.debug", "ssl"); which enabled debug level logging. Now the logs are much shorter and precise. It was also apparent that the logs weren't from commons-net library after all, but from the javax.net. The log is much shorter and looks something like below-

Jul 30, 2012 9:03:16 AM com.mff.ftps.FTPSSLTool main
INFO: Connecting to IP: xxx.xxx.xxx.xxx on Port: 890
Jul 30, 2012 9:03:16 AM com.mff.ftps.FTPSSLTool main
INFO: # Initiating SSL connection
Jul 30, 2012 9:03:16 AM com.mff.ftps.FTPSSLTool main
INFO: # Invoking Trust Manager
Jul 30, 2012 9:03:16 AM com.mff.ftps.FTPSSLTool main
INFO: # Connect Call
220 GlobalSCAPE Secure FTP Server
USER XXXXXXX
331 Password required for XXXXXXX.
PASS XXXXXXXXX
230 Login OK. Proceed.
Jul 30, 2012 9:03:22 AM com.mff.ftps.FTPSSLTool main
INFO: # Login Success
TYPE A
200 Type set to A.
PBSZ 0
200 PBSZ Command OK. Protection buffer size set to 0.
PROT P
200 PROT Command OK. Using Private data connection
Jul 30, 2012 9:03:24 AM com.mff.ftps.FTPSSLTool main
INFO: Connected to xxx.xxx.xxx.xxx .
CWD /Data/Inv
Jul 30, 2012 9:03:24 AM com.mff.ftps.FTPSSLTool main
INFO: # Invoked Directory mode
250 Folder changed to "/Data/Inv".
SYST
215 UNIX Type: L8
PASV
227 Entering Passive Mode (216,153,173,246,109,220).
LIST /Data/Inv
150 Opening ASCII mode data connection for file list.
226 Transfer complete. 1430 bytes transferred. 1278 Bps.
Jul 30, 2012 9:03:30 AM com.mff.ftps.FTPSSLTool main
INFO: # FTP Client disconnected

Answer 1

You can set the log level of your application using setLevel(). The class Level is used to define which messages should be written in the log. You can set one of the following Log Levels:

• Level.SEVERE (highest level)
• Level.WARNING
• Level.INFO
• Level.CONFIG
• Level.FINE
• Level.FINER
• Level.FINEST

If you use LOGGER.setLevel(Level.INFO), every log level higher or equal INFO will be written in the log, i.e, SEVERE, WARNING and INFO. Also, you have the levels Level.OFF and Level.ALL to turn the logging off or to log everything.

Add to your application a higher log level, such as logger.setLevel(Level.SEVERE).

Example

public void writeLog() {
    // Set the LogLevel to Severe, only severe Messages will be written
    LOGGER.setLevel(Level.SEVERE);
    LOGGER.severe("Severe Log");
    LOGGER.warning("Warning Log");
    LOGGER.info("Info Log");
    LOGGER.finest("Really not important");

    // Set the LogLevel to Info, severe, warning and info will be written
    // Finest is still not written
    LOGGER.setLevel(Level.INFO);
    LOGGER.severe("Severe Log");
    LOGGER.warning("Warning Log");
    LOGGER.info("Info Log");
    LOGGER.finest("Really not important");
}

More information: http://www.vogella.com/articles/Logging/article.html

P.S. be careful with your logging.properties file which sets your global log level.

Answer 2

I think you are looking in the wrong place; those messages are not from the apache commons net library.

I think they are from the IBMJSSEProvider2 you see referred in the first lines. According to this link, you should be able to disable them by not setting the system property javax.net.debug, or redirect them with the os400.stdout and os400.stderr properties.

Answer 3

Well, I've had the same issue with Spring, Quartz, Hibernate etc. APIs and frameworks creating huge boulders of logs.

I set custom levels for each of the APIs on a per package basis.

• logger.org.spring = WARN
• logger.org.hibernate = DEBUG
• logger.org.quartz = INFO
• logger.com.myApp = DEBUG

Of course this is not the complete property set, but you get the idea. You could use the package name - org.apache.commons and assign a log level to that package. Please note : Any and every log from any class under that package level would be configured with the same level as this.

I used slf4j over log4j ( http://www.slf4j.org/) , instead of util logger. But I'm sure the fix could be twisted a bit in your situation. If I might be a little bold, I'd recommend using SLF4J. HTH.

Answer 4

expect the apache-commons-net logging to use either commons-logging or SLF4J - in the absence of any other controlling factors, these should route logging to java.util.logging.

The ultimate answer here is that IF you're seeing the logs intermixed in an output file (not console), then it is highly likely that they ARE being routed through a common logger. And java.lang.logging is at work here, so let's try configuration.

To configure java.util.logging:

Create your logging properties file, say myLog.properties, and customize levels for the different packages. For example, set a level higher than INFO - such as SEVERE - for the obnoxious package com.mff.ftps:

# handlers=java.util.logging.ConsoleHandler, java.util.logging.FileHandler
handlers=java.util.logging.FileHandler

# Set ROOT logger level
.level=INFO
com.mff.ftps.level=SEVERE
# Set any number specifications: <package.path>.level=<LOGLEVEL>

java.util.logging.ConsoleHandler.level=WARNING
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

java.util.logging.FileHandler.level=FINEST
java.util.logging.FileHandler.pattern=myLogFile.log
java.util.logging.FileHandler.limit=1073741824  # 1MB
java.util.logging.FileHandler.count=2
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

When you start java, specify the logging properties file:

java -Djava.util.logging.config.file=<pathTo>/myLog.properties -cp ...

or write code:

File logPropFile = new File("<pathTo>/myLog.properties");
InputStream logPropStream = new FileInputStream(logPropFile);
try {
    LogManager.getLogManager().readConfiguration(logPropStream);
}
finally {
    logPropStream.close();
}