Enabling method parameters logging in Java logging

Yes, I can log some information at

// Generator.java

package sorter;

import java.util.Vector;

import java.rmi.Remote;

import java.rmi.RemoteException;

public interface Generator extends Remote{

public Vector generate(int num) throws RemoteException;

}

// -- end Generator.java

// -- start GeneratorImpl.java

package sorter;

import java.rmi.*;

import java.util.Vector;

import java.util.Random;

import java.rmi.server.UnicastRemoteObject;

public class GeneratorImpl

extends UnicastRemoteObject implements Generator{

public GeneratorImpl() throws RemoteException{

}

public Vector generate(int num)

throws RemoteException{

Random r = new Random(

java.util.Calendar.getInstance().getTime().getTime());

Vector vec = new Vector();

for(int i = 0; i < num; i ++){

vec.add(i, new Integer(r.nextInt() % 100) );

}

return vec;

}

}

// -- end GeneratorImpl.java

// start Servers.java

package sorter;

import java.rmi.RMISecurityManager;

import java.rmi.Naming;

import java.util.logging.*;

public class Servers {

public static void main(String args[]) {

// Create and install a security manager

if (System.getSecurityManager() == null) {

System.setSecurityManager(new RMISecurityManager());

}

try {

// run generator

GeneratorImpl gen = new GeneratorImpl();

// Bind this object instance to the name "HelloServer"

Naming.rebind("//localhost/GeneratorServer", gen);

} catch (Exception e) {

System.out.println("Servers err: " + e.getMessage());

e.printStackTrace();

}

}

}

// Client.java

package sorter;

import java.rmi.*;

import java.rmi.registry.*;

import java.rmi.server.*;

import java.util.Date;

import java.util.Vector;

import java.util.logging.*;

public class Client{

public static void main(String[] argv) {

String serverName = "";

Generator gen = null;

Vector vec = null;

System.setSecurityManager(new RMISecurityManager());

if (argv.length != 1) {

try {

serverName = java.net.InetAddress.getLocalHost().getHostName();

}

catch(Exception e) {

e.printStackTrace();

}

}

try {

//bind server object to object in client

gen = (Generator) Naming.lookup("//" + serverName + "/GeneratorServer");

//Print success message

System.out.println("RMI connection to GeneratorServer successful...");

//Call method on server and put result into String message

vec = gen.generate(11);

//Print message on server

System.out.println("Value " + vec);

}

catch(Exception e) {

System.out.println("Exception occurred: " + e);

System.exit(0);

}

}

}

// end Client.java

// clientlog.props

handlers=java.util.logging.FileHandler

.level=ALL

sorter.level=ALL

sorter.Client.level=ALL

java.util.logging.FileHandler.pattern=/tmp/log/client%u.log

java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

// end clientlog.props

// start serverlog.props

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

.level=ALL

sorter.level=ALL

java.util.logging.ConsoleHandler.level=SEVERE

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

java.util.logging.FileHandler.level=ALL

java.util.logging.FileHandler.pattern=/tmp/log/server%u.log

java.util.logging.FileHandler.limit=50000

java.util.logging.FileHandler.count=1

java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

// end severlog.props

// start rmi.policy

grant {

// Allow everything for now

permission java.net.SocketPermission "*:1024-65535", "accept, connect, listen";

permission java.security.AllPermission;

permission java.io.FilePermission "/tmp/log/*", "write, read";

permission java.util.logging.LoggingPermission "control";

};

// end rmi.policy

I wrote a very simple RMI program I showed above that generates random vector of integer numbers and ran it with command:

$rmiregistry

$java -Djava.security.policy=file:/jbproject/sorter/rmi.policy -Djava.util.logging.config.file=/jbproject/sorter/serverlog.props sorter.Servers

$java -Djava.security.policy=file:/jbproject/sorter/rmi.policy -Djava.util.logging.config.file=/jbproject/sorter/clientlog.props sorter.Client

And I got the following log output in /tmp/log:

///-- client0.log

..........................

2004-08-10 11:12:53 sun.rmi.server.UnicastRef invoke

FINER: main: method: public abstract java.util.Vector sorter.Generator.generate(int) throws java.rmi.RemoteException

2004-08-10 11:12:53 sun.rmi.server.UnicastRef logClientCall

FINER: main: outbound call: [endpoint:[192.168.0.1:36424](remote),objID:[19ee1ac:fe47f89fa9:-8000, 0]] : sorter.GeneratorImpl_Stub[19ee1ac:fe47f89fa9:-8000, 0]: public abstract java.util.Vector sorter.Generator.generate(int) throws java.rmi.RemoteException

2004-08-10 11:12:53 sun.rmi.transport.tcp.TCPChannel newConnection

FINE: main: reuse connection

2004-08-10 11:12:53 sun.rmi.server.UnicastRef invoke

FINER: main: opnum = 7324764122476237606

2004-08-10 11:12:53 sun.rmi.transport.StreamRemoteCall <init>

FINER: main: write remote call header...

................

// -- end client0.log

// -- server0.log

.....................

2004-08-10 11:12:49 sun.rmi.transport.ObjectTable putTarget

FINER: main: add object [0]

2004-08-10 11:12:49 sun.rmi.server.UnicastServerRef computeMethodHash

FINER: main: string used for method hash: "generate(I)Ljava/util/Vector;"

2004-08-10 11:12:49 sun.rmi.server.UnicastRef newCall

FINE: main: get connection

2004-08-10 11:12:49 sun.rmi.transport.tcp.TCPChannel createConnection

FINE: main: create connection

........................

// -- end server0.log

You can see that sorter.Generator.generate(int) is invoked. And please notice that there is no single line in the source code with Logger, or log() apart from config files.

As far as I can understand logging mechanisms is embedded in JDK so I only need to enable it and configure. Of course I can put log() statements in the soruce code if I wish. But I can get some information about execution without any additional instruction put into my source code. Please notice, that this is the FINER level and you can read in documentation that entering() and exiting() also log information at FINER level (as I remember). So if I configure to log ALL actions why I cannot enable also logging method invocation with parameter values without additional instrumentation of my source code.

However, thank you 'kajbj'.

Saer at 2007-7-5 21:34:24 >

Hi Kaj,

I am just looking around the matter since I am not familiar with logging facility (I have been just learning it since Sunday) - I try log4j but it seems not so powerful as JDK 1.4 logging (by the way it looks as JDK incorporated main concepts from log4j).

It helps me a lot since it means that I need to write a proxy object and instrument code at the proxy level or it means that I should instrument the rmi stubs in order to log parameters or returned values.

Currently I am reading and exercising the AspectJ as you suggested. However, I am not pretty sure if I can use it for RMI applications since AspectJ uses its own compiler. Do you know anything if RMI works fine with AspectJ?

Thanks.

Saer at 2007-7-5 21:34:24 >

> My advice would be to learn logging without AspectJ

> for now. Aspects might be very important someday, but

> you can solve your fundamental logging problem without

> it today.

>

I totally agree with duffymo, you probably don't want to use Aspects, it's just an interesting concept. It's better if you add logging statements to your code.

/Kaj

kajbj at 2007-7-5 21:34:24 >

The ONLY time you might need stuff like

if (logger.isLoggable(Level.FINEST))

{

}

would be if you were concatenating some strings to create a logging message. This can be an expensive operation, especially if your code is peppered with them. Surrounding those cases with this IF test gives the Hotspot compiler a chance to eliminate the operation.

%

duffymo at 2007-7-5 21:34:24 >

> 'duffymo': Yes, I can do that but I need as Kaj and

> you say first to log something i.e. put lines with

> logger.entering() and logger.exiting(). And I would

> like not to instrument the source code and I would

> like to have a log. It means that:

You have no choice. You have to instrument the source code. Can't have logging without it. Even AspectJ isn't magic that way. You have to tell the JVM where to do it somewhere. All AspectJ does is move it out of your code and into deployment descriptors.

Rod Johnson says that writing a class means instrumenting it for logging. I take that advice to heart. That's what I do from now on.

> 1. I should have an instrumented JVM (but it would be

> probably much more slower). However, I should do it

> on my own.

But you don't.

> 2. I should put log instructions somewhere (to stubs,

> source code, or proxies, etc.) and then use logging

> facility supported by JDK 1.4.

Right.

> As Kaj has said: it is not possible to log without logging.

Indeed.

> Concerning log4j, I think that I will be politically

> correct if I say that log4j is so good that it has

> been incorporated into official JDK 1.4 release. Make

> peace not war.

Fine with me. I'm not one of those folks who's upset about log4j. They all work at IBM. ;) I'm just pointing out the history.

%

duffymo at 2007-7-5 21:34:24 >