log4j properties file - how to set threshold for socket appender?

Question

I have some problems with setting Threshold in properties file.

I created two files:

log4j-server.properties

log4j.rootLogger=ERROR, CA, FA

#
log4j.appender.CA=org.apache.log4j.ConsoleAppender
log4j.appender.CA.layout=org.apache.log4j.PatternLayout
log4j.appender.CA.layout.ConversionPattern=[%d] [%t] [%m]%n
log4j.appender.CA.Threshold=DEBUG

#
log4j.appender.FA=org.apache.log4j.FileAppender
log4j.appender.FA.File=result.log
log4j.appender.FA.layout=org.apache.log4j.PatternLayout
log4j.appender.FA.layout.ConversionPattern=[%d] [%t] [%m]%n
log4j.appender.FA.Threshold=DEBUG

and log4j.properties

log4j.rootLogger=DEBUG, server

log4j.appender.server=org.apache.log4j.net.SocketAppender
log4j.appender.server.Port=4712
log4j.appender.server.RemoteHost=localhost
log4j.appender.server.ReconnectionDelay=10000

and I get logs:

INFO [2012-08-02 11:14:27,490] [main] [Listening on port 4712]
INFO [2012-08-02 11:14:27,490] [main] [Waiting to accept a new client.]
INFO [2012-08-02 11:14:37,669] [main] [Connected to client at /127.0.0.1]
INFO [2012-08-02 11:14:37,669] [main] [Starting new socket node.]
INFO [2012-08-02 11:14:37,669] [main] [Waiting to accept a new client.]
INFO [2012-08-02 11:14:41,385] [main] [Connected to client at /127.0.0.1]
INFO [2012-08-02 11:14:41,385] [main] [Starting new socket node.]
INFO [2012-08-02 11:14:41,401] [main] [Waiting to accept a new client.]
INFO [2012-08-02 11:14:41,385] [request1343898881385] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:41,526] [SimpleSocketServer-4712] [Caught java.net.SocketException closing conneciton.]
INFO [2012-08-02 11:14:42,228] [main] [Connected to client at /127.0.0.1]
INFO [2012-08-02 11:14:42,228] [main] [Starting new socket node.]
INFO [2012-08-02 11:14:42,228] [main] [Waiting to accept a new client.]
INFO [2012-08-02 11:14:42,228] [request1343898882228] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:42,353] [SimpleSocketServer-4712] [Caught java.net.SocketException closing conneciton.]

while I need logs generated only by my program, not messages generated by the socket server itself

INFO [2012-08-02 11:14:41,385] [request1343898881385] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:41,510] [request1343898881385] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:42,228] [request1343898882228] [public static void hello.RMIClient.main(java.lang.String[])]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public java.lang.String hello.Hello.greeting(java.lang.String)]
INFO [2012-08-02 11:14:42,353] [request1343898882228] [public static void hello.RMIClient.main(java.lang.String[])]

I have tried almost every configuration, but I couldn't find a solution.

EDIT: I added -Dlog4j.debug=true line

and I got

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@35ce36.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@35ce36 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@35ce36.
log4j: Trying to find [log4j.properties] using sun.misc.Launcher$AppClassLoader@35ce36 class loader.
log4j: Trying to find [log4j.properties] using ClassLoader.getSystemResource().
log4j: Could not find resource: [null].
log4j: Parsing for [root] with value=[DEBUG, CA, FA].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "CA".
log4j: Parsing layout options for "CA".
log4j: Setting property [conversionPattern] to [%p [%d] [%t] [%m]%n].
log4j: End of parsing for "CA".
log4j: Setting property [threshold] to [DEBUG].
log4j: Parsed "CA" options.
log4j: Parsing appender named "FA".
log4j: Parsing layout options for "FA".
log4j: Setting property [conversionPattern] to [[%d] [%t] [%m]%n].
log4j: End of parsing for "FA".
log4j: Setting property [threshold] to [DEBUG].
log4j: Setting property [file] to [result.log].
log4j: setFile called: result.log, true
log4j: setFile ended
log4j: Parsed "FA" options.
log4j: Finished configuring.

EDIT: After changing conversion pattern |I got

INFO  [2012-08-02 12:13:11,278] [main] org.apache.log4j.net.SimpleSocketServer Listening on port 4712
INFO  [2012-08-02 12:13:11,278] [main] org.apache.log4j.net.SimpleSocketServer Waiting to accept a new client.
INFO  [2012-08-02 12:13:22,125] [main] org.apache.log4j.net.SimpleSocketServer Connected to client at /127.0.0.1
INFO  [2012-08-02 12:13:22,125] [main] org.apache.log4j.net.SimpleSocketServer Starting new socket node.
INFO  [2012-08-02 12:13:22,125] [main] org.apache.log4j.net.SimpleSocketServer Waiting to accept a new client.
INFO  [2012-08-02 12:13:25,664] [main] org.apache.log4j.net.SimpleSocketServer Connected to client at /127.0.0.1
INFO  [2012-08-02 12:13:25,664] [main] org.apache.log4j.net.SimpleSocketServer Starting new socket node.
INFO  [2012-08-02 12:13:25,664] [main] org.apache.log4j.net.SimpleSocketServer Waiting to accept a new client.
INFO  [2012-08-02 12:13:25,664] [request1343902405664] aspects.ReportingAspect public static void hello.RMIClient.main(java.lang.String[])
INFO  [2012-08-02 12:13:25,789] [request1343902405664] aspects.ReportingAspect public java.lang.String hello.Hello.greeting(java.lang.String)
INFO  [2012-08-02 12:13:25,789] [request1343902405664] aspects.ReportingAspect public java.lang.String hello.Hello.greeting(java.lang.String)
INFO  [2012-08-02 12:13:25,789] [request1343902405664] aspects.ReportingAspect public static void hello.RMIClient.main(java.lang.String[])
INFO  [2012-08-02 12:13:25,789] [SimpleSocketServer-4712] org.apache.log4j.net.SocketNode Caught java.net.SocketException closing conneciton.

Answer 1

You need to understand how log4j applies thresholds:

First the threshold of the logger is applied. If the logger doesn't have one, then the threshold of the parent logger is applied. If the message can't pass any of these, no appender will ever see it.

In the next step, all appenders will see the message and they will again filter it using their threshold.

So if the threshold of any logger is higher than that of the appender, the appender will never see the message.

How can you solve that? You can use a logger that is "closer" to the message source. If you want to log from a class below com.something.x.y.z, you can define a logger for com and give it a threshold + an appender.

It will see messages before the root logger, so you can use that to redirect parts of the messages.

Also keep in mind that using package/class names is just a convenience. Logger names can be anything. So you could define a logger called RMI or network and use that. Since it's not part of the usual logger hierarchy, only specific messages will go there.

Just don't forget to set additive to false as necessary to make sure messages are processed only once.

[EDIT] My guess is that the wrong config is read. Add -Dlog4j.debug=true to the command line to see which config files log4j reads and how it configures itself.

[EDIT2] Use the log pattern %-5p [%d] [%t] %c %m%n to see which logger creates which message. You can then raise the threshold of the ones that you don't want.