Redirecting traceStack to a file

[rombert]

Hi,

I would like, for debugging purposes, to redirect certain very verbose traces to a different log. By inspecting the code in the Helper class, I arrived at the conclusion that I should invoke the Helper.openTrace method as early as possible, and ended up with:

########################################################################
#
# Rule to set the logger eagerly
#
RULE Set logger
CLASS com.example.App
METHOD main
AT ENTRY
IF TRUE
DO openTrace("socketOperations", "/usr/local/app/logs/socketOperations.log")
ENDRULE

########################################################################
#
# Rule to trace ServerSocket creation
#

RULE ServerSocket trace create
CLASS java.net.ServerSocket
METHOD <init>(int, int, InetAddress)
AT EXIT
IF TRUE
DO traceStack("*** server create " + $0, "socketOperations", 15)
ENDRULE

Unfortunately the first rule, when added, prevents any output from being written. Without it, that is just with the "socketOperations" identifier, the logs goes to /usr/local/app/trace0000000 .

How can I redirect the traceStack calss for the "socketOperations" identifier to another file?

Thanks,

Robert

[adinn]

Hi Robert,

Your post got a bit mangled -- I'll try reformatting it:

Robert Munteanu wrote:

Hi,

I would like, for debugging purposes, to redirect certain very verbose traces to a different log. By inspecting the code in the Helper class, I arrived at the conclusion that I should invoke the Helper.openTrace method as early as possible, and ended up with:

# Rule to set the logger eagerly

RULE Set logger

CLASS com.example.App

METHOD main

AT ENTRY

IF TRUE

DO openTrace("socketOperations", "/usr/local/app/logs/socketOperations.log")

ENDRULE

# Rule to trace ServerSocket creation

RULE ServerSocket trace create

CLASS java.net.ServerSocket

METHOD (int, int, InetAddress)

AT EXIT

IF TRUE

DO traceStack("*** server create " + $0, "socketOperations", 15)

ENDRULE

Unfortunately the first rule, when added, prevents any output from being written. Without it, that is just with the "socketOperations" identifier, the logs goes to /usr/local/app/trace0000000 .

How can I redirect the traceStack class for the "socketOperations" identifier to another file?

Hmm, that sounds like it may be a bug in openTrace. However, it may also be a deadlock up occurring because your rule is being triggered early on during bootstrap. I will probably need a few more details before I can debug this.

Which Byteman release are you using?

What is your command line?

Can you post the code which is locking up? If not, then a test program whicih also manifests the problem woudl help

Meanwhile, I'll try reproducing this on trunk by writing a simple  test program which exercises both your rules.

regards,

Andrew Dinn

[rombert]

Hi Andrew,

Thanks for the prompt reply. I'm using Byteman 1.3.0 .

I just double-checked, and it seems that the output is still being written to the trace000000 file. I assume that this is because I have the following system properties set:

-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1555

, which means that a port is open before my main method is called, and therefore my first rule does not have any effect.

Indeed, the first trace is

*** server bind ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=53576]java.net.ServerSocket.bind(ServerSocket.java:329)
java.net.ServerSocket.<init>(ServerSocket.java:185)
java.net.ServerSocket.<init>(ServerSocket.java:97)
sun.rmi.transport.proxy.RMIDirectSocketFactory.createServerSocket(RMIDirectSocketFactory.java:27)
sun.rmi.transport.proxy.RMIMasterSocketFactory.createServerSocket(RMIMasterSocketFactory.java:333)
sun.rmi.transport.tcp.TCPEndpoint.newServerSocket(TCPEndpoint.java:649)
sun.rmi.transport.tcp.TCPTransport.listen(TCPTransport.java:299)
sun.rmi.transport.tcp.TCPTransport.exportObject(TCPTransport.java:218)
sun.rmi.transport.tcp.TCPEndpoint.exportObject(TCPEndpoint.java:393)
sun.rmi.transport.LiveRef.exportObject(LiveRef.java:129)
sun.rmi.server.UnicastServerRef.exportObject(UnicastServerRef.java:190)
sun.management.jmxremote.ConnectorBootstrap$PermanentExporter.exportObject(ConnectorBootstrap.java:172)
javax.management.remote.rmi.RMIJRMPServerImpl.export(RMIJRMPServerImpl.java:84)
javax.management.remote.rmi.RMIJRMPServerImpl.export(RMIJRMPServerImpl.java:75)
javax.management.remote.rmi.RMIConnectorServer.start(RMIConnectorServer.java:388)

So my question becomes: how can I specify a log file for a certain identifier, given that I have no control over when that identifier is first used , as it comes before my main method invocation?

Thanks,

Robert

[adinn]

Robert Munteanu wrote:

Hi Andrew,

Thanks for the prompt reply. I'm using Byteman 1.3.0 .

I just double-checked, and it seems that the output is still being written to the trace000000 file. I assume that this is because I have the following system properties set:

-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1555

, which means that a port is open before my main method is called, and therefore my first rule does not have any effect.

Indeed, the first trace is

*** server bind ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=53576]java.net.ServerSocket.bind(ServerSocket.java:329)
java.net.ServerSocket.<init>(ServerSocket.java:185)
java.net.ServerSocket.<init>(ServerSocket.java:97)
sun.rmi.transport.proxy.RMIDirectSocketFactory.createServerSocket(RMIDirectSocketFactory.java:27)
sun.rmi.transport.proxy.RMIMasterSocketFactory.createServerSocket(RMIMasterSocketFactory.java:333)
sun.rmi.transport.tcp.TCPEndpoint.newServerSocket(TCPEndpoint.java:649)
sun.rmi.transport.tcp.TCPTransport.listen(TCPTransport.java:299)
sun.rmi.transport.tcp.TCPTransport.exportObject(TCPTransport.java:218)
sun.rmi.transport.tcp.TCPEndpoint.exportObject(TCPEndpoint.java:393)
sun.rmi.transport.LiveRef.exportObject(LiveRef.java:129)
sun.rmi.server.UnicastServerRef.exportObject(UnicastServerRef.java:190)
sun.management.jmxremote.ConnectorBootstrap$PermanentExporter.exportObject(ConnectorBootstrap.java:172)
javax.management.remote.rmi.RMIJRMPServerImpl.export(RMIJRMPServerImpl.java:84)
javax.management.remote.rmi.RMIJRMPServerImpl.export(RMIJRMPServerImpl.java:75)
javax.management.remote.rmi.RMIConnectorServer.start(RMIConnectorServer.java:388)

So my question becomes: how can I specify a log file for a certain identifier, given that I have no control over when that identifier is first used , as it comes before my main method invocation?

Thanks,

Robert

That could very well be the cause. Another possibility is that the directory path to your trace file is invalid because some of the directories do not exist (I just ran into that one :-).

If the problem is that the trace rule is triggering before the traceOpen rule then there are two possible solutions I can suggest.

1) Clearly, if you are injecting trace calls into VM code then it is always possible for your injected trace ruel to get triggered before main is run. One way to fix this is toinject your traceOpen call into some code which runs first. Luckily you know where the this happens. So, try attaching your 'Set logger' rule to  RMIConnectorServer.start. If that always runs first then you are ok.

If you find that other threads are also opening sockets and this does not always run first then you could also attach your 'Set logger' rule to ServerSocket.<init>. It will do no harm if the openTrace call gets run multiple times. However, you could use a flag to make sure it is only added once which will be slightly more efficient:

RULE Set logger
CLASS ServerSocket
METHOD <init>(int, int, InetAddress)
AT ENTRY
IF flag("socketOperations")
DO openTrace("socketOperations", "/usr/local/app/logs/socketOperations.log")
ENDRULE

2) You can use your own helper class to override the implementation of trace so that it uses the file name you want:

public class MyHelper extends Helper

{

  public trace(Object id, String message)

  {

    if (id instanceof String && !id.equals("out") && !id.equls("err") {

      openTrace(id, "/usr/local/app/logs/" + id + ".log);

    }

    trace(id, message);

  }

}

Put the helper class in  your classpath (or get the agent to add it) and add the line

HELPER org.my.MyHelper

before your first rule. Then all your trace calls will automatically open the file if the object id is a simple string.

[rombert]

Andrew Dinn wrote:

1) Clearly, if you are injecting trace calls into VM code then it is always possible for your injected trace ruel to get triggered before main is run. One way to fix this is toinject your traceOpen call into some code which runs first. Luckily you know where the this happens. So, try attaching your 'Set logger' rule to  RMIConnectorServer.start. If that always runs first then you are ok.

If you find that other threads are also opening sockets and this does not always run first then you could also attach your 'Set logger' rule to ServerSocket.<init>. It will do no harm if the openTrace call gets run multiple times. However, you could use a flag to make sure it is only added once which will be slightly more efficient:

I have attached the set logger rule ServerSocket.<init> AT ENTRY, and it works just fine now.

Thank you for your help ( not to mention a great app ).

Robert

[adinn]

Glad to help

Robert Munteanu wrote:

I have attached the set logger rule ServerSocket.<init> AT ENTRY, and it works just fine now.

Thank you for your help ( not to mention a great app ).

Thanks for the compliment. I hope you find it useful and wll encourage others to use it. Please post again if you have more problems or just to report any success you have had.

Can you tell me anything about what you are using Byteman for? It is still fairly new and I am trying to get a feel  for what people are doing with it. Thanks for any info you can provide.

regards,

Andrew Dinn

[rombert]

Can you tell me anything about what you are using Byteman for? It is still fairly new and I am trying to get a feel  for what people are doing with it. Thanks for any info you can provide.

I'm using it to debug some a situation where a Java application - which acts as a container for running other apps - runs out of file descriptors. There is no evidence about the leak except some sockets which can't be identified by lsof , are not shown by netstat, are not registered in /proc/net/* and listed just as socket ids in /proc/$PID/fd .

I've posted about this in more detail on ServerFault: sockets found by lsof but not by nestat.I remembered Byteman after someone suggested that I try and track down all socket-related calls.

Robert