6 Replies Latest reply on Jun 29, 2010 8:42 AM by Robert Munteanu

    Redirecting traceStack to a file

    Robert Munteanu Newbie

      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

        • 1. Re: Redirecting traceStack to a file
          Andrew Dinn Master

          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

          • 2. Re: Redirecting traceStack to a file
            Robert Munteanu Newbie

            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

            • 3. Re: Redirecting traceStack to a file
              Andrew Dinn Master

              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.

              • 4. Re: Redirecting traceStack to a file
                Robert Munteanu Newbie

                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

                • 5. Re: Redirecting traceStack to a file
                  Andrew Dinn Master

                  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

                  • 6. Re: Redirecting traceStack to a file
                    Robert Munteanu Newbie
                    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