10 Replies Latest reply on Feb 16, 2016 6:08 AM by adinn

    Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]

    adinn

      Intro

       

      I have had a few thoughts about what is needed to improve the behaviour of Byteman debug and verbose mode tracing (the task covered by BYTEMAN-249) which I want to sumamrize in this discussion. None of thsi is cast in stone -- it's just ideas.

       

      There are two aspects to this when it comes to designing an improved tracing mechanism:

       

      • how to provide a better way for users to select which trace messages they see
      • how to implement that selective tracing.

       

      The 3rd stage of the task will then involve employing the new APIs, firstly to change over all existing trace statements to use it and then to reorganise and extend the existing trace to improve the quality of the trace messgages that are generated and ensure that they actually conform to the user's selection criteria.

       

      A key goal of the design task is to retain some sort fo compatibility with the existing configuration model i.e. to continue to support debug and verbose tracing levels using some simple switch which enable either debug trace on its own or both debug and verbose trace.

       

      That is not to imply that all trace messages currently output in accordance with those two switches should continue to be output nor that new messages should not be included. The mechanism shoud be retained but the trace which results will almost certainly require dropping some messages genertaed when debug or verbose is set and adding some other new ones when verbose is set. For example, configuring debug is only supposed to enable messages generated when a rule includes a call to the Helper debug method but, at present, the agent outputs a few messages of its own when debug is enabled. Similarly, the agent does not always print trace when parse, typecheck or compileor failures occur even when verbose is set; these really should be notified (with stack trace) without the need for the user to employ any more noissy trace level.

       

      What I am proposing is that we keep the existing 2 levels of trace and supplement them with a 3rd level which can be configured to be selective. It should work roughly as follows:

       

        debug

        verbose

        noisy

       

      debug trace

       

      debug trace is enabled by setting org.jboss.byteman.debug. Setting this property enables output of debug statements from method Helper.debug It does not enable any other trace output. Helper.debug is responsible for checking whether to print any output by calling Transformer.isDebug().

       

      Currently Helper debug() prints directly to System.out. It shoud be modified so that the print operation is performed by calling traceln("dbg", "DBG: " + message). This variant of method Helper.traceln looks for for a trace stream (a PrintStream instance in the trace stream hash table) identified by the key supplied in the fist argument and uses it do the actual printing. If no such stream exists it uses System.out.

       

      This will allows all debug messages to be redirected simply by adding an entry to the trace stream hash map with key "dbg". By default System.out will be the target for this trace stream but we can also allow it to be configured to System.error or an actual file using System property org.jboss.byteman.debug.tracestream. If this is set to "out" or "err" then the trace stream "dbg" will be set to idenitfy System.out or System.err. If set to any other string that will be used as a file name to which trace will be redirected (Assuming the file can be opened).

       

      verbose trace

       

      verbose trace is enabled by setting org.jboss.byteman.verbose. Setting this property should continue to enable output of all existing verbose trace statements which are currently implemented by testing Transformer.isVerbose() and then calling System.out.println. The use of isVerbose() to guard the calls to print the messages should still be retained. However, the actual printing should be implemented by planting a call to Helper.verbose(message). This shoud redirect to call Helper.traceln("vrb", "VRB: " + message). As with debug the trace stream "vrb" wil idenitfy System.out by default but can be redirected by calling traceOpen. We can also allow it to be configured using system property org.jboss.byteman.verbose.tracestream.

       

      noisy trace

       

      noisy trace is enabled by setting org.jboss.byteman.noisy. This switches on highly detailed tracing of operation of a range of different Byteman operations. Tracing can be filtered by selecting trace messages which fall into one or more trace categories. Enabling noisy trace also enables verbose and debug trace.

       

      Setting the noisy property with no other configuration will enable trace for a default set of trace categories. Other categories may be selected by setting org.jboss.byteman.noisy.categories to a string value idenitifyng the desired trace categories. An empty string will configure the default set. A string containing one or more of the following categories (using | as a separator) will enable trace output for any trace operation which is relevant to that category:

       

        PARSE|TYPE|INTERP|COMP|MATCH|INJECT|CFG|CFGPART|GEN|GENPART|HELPER||LOAD|LISTEN|INVALID|WTF|???

       

      The default set of categories will include LOAD|LISTEN|MATCH|PARSE|TYPE|HELPER|???

       

      n.b. these are just rough guesses at what sort of categories are needed. It may be that they need revising and/or supplementing with other categories. Also, note that the trace categories are not meant to be distinct, non-overlapping groups. If a message is relevant to more than one trace category then it shoudl be output whenever any of the relevant categories is enabled.

       

      At the point where noisy trace is generated the trace operation will be guarded by an if whose condition is a call to Transformer.isNoisy(int). The argument will be constructed by ORing in flags which identify the trace categories to which the trace message belongs. The same flags should be passed in a call to Helper.noisyln which is used to print the trace message e.g.

       

        if (isNoisy(Trace.HELPER|Trace.INVALID)) {

          Helper.noisy(Trace.HELPER|Trace.INVALID,

                         "Helper class has lifecycle method with wrong signature " +

                            helperClassName + "." +

                            helperMethodName + helperMethodSignature);

        }

       

      Helper.isNoisy will return true if any of the trace categories identified in the input mask are enabled. If none of them are enabled it wil lreturn falseHelper.noisy(inputMask, message)  will redirect to a call to Helper.traceln("nzy", "NZY: " + flagString(inputMask) + message). The first argument directs the trace to the "nzy" trace stream. This will default to System.out but can be reset by means of a call to traceOpen. We can also allow it to be configured using system property org.jboss.byteman.noisy.tracestream.  flagString is method which constructs a string containing a label for each trace categories mentioned in inputMask which is actually enabled. For exmaple, if inputMask is Trace.HELPER|Trace.INVALID and the HELPER category has been enabled but the INVALID category has not been enabled the flagmask will simply be "HELPER: ". If both flags are enabled then it will be "HELPER: INVALID: ".

       

      Trace messages at the noisy level will mostly need to be added as new. One or two of the existing verbose trace messages and information generated via other trace mechanisms (such as dumping of CFG info or generated bytecode) may also need to be configured and generated under control of the noisy trace mechanism.

       

      What next

       

      So, I think what is needed now is this

       

      • check that this will actually operate in a useful way
      • check that my vague guesses about how to implement this via Helper.traceln and using trace streams actually makes sense
      • implement the relevant behaviour in class Helper
      • modify existing System.out.println statements guarded by isDebug or isVerbose to use the new Helper.verbose
        n.b. Helper.debug is only meant to be called from user supplied rule code so any calls internal to Byteman need to use Helper.verbose()
      • idenitfy any verbose messages which really ought to be output as noisy messages and modify the trace guards/calls to use the isNoisy() & noisy()
      • convert the trace output by the CFG classes to use noisy trace.
        This is currently controlled by setting the system properties o.j.b.dump.cfg and o.j.b.dump.cfg.partial so we need to make sure that when these properties are set we enable noisy trace for (at least) the CFG/CFGPART trace classes)
      • see what we can do to configure bytecode dumping using the noisy trace settings (DUMP and DUMPPART)
        obviously we won't use Helper.noisy() to dump bytecode in classfile format  but we can still use isNoisy(DUMP|DUMPPART) and isNoisy(DUMPPART) to test whether or not we should dump bytecode.
        This is controlled by setting the system properties o.j.b.dump.generated.classes and o.j.b.dump.generated.classes.intermediate so we need to make sure that when these properties are set we enable noisy trace for (at least) the GEN|GENPART trace classes)
        • 1. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
          adinn

          Filippe and I continued this discussion in email but really should have done so on the fourm. Here are the relevant parts of the exchange.

           

          About the traceln calls: traceln("dbg", "DBG: " + message). I think better change the DBG to DEBUG, VRB to VERBOSE and
          NZY to NOIZY, some user can not understand the log messages started with DBG, VRB, NZY.
          Ok, sure we will use those prefixes -- except if you are going to spell these words out the the correct spelling is NOISY not NOIZY.  
          When enable the verbose the trace should be enabled also? 
          Enabling debug does /not/ enable verbose trace. Debug trace is for end-users and not for generate Byteman-internal trace. Setting
          org.jboss.byteman.debug switches on output from /public/ method Helper.debug(). That method is a public instance method because
          public instance methods of Helper can be used for built-in calls in Byteman rules.  The new methods that I suggested we use to
          implement internal trace, Helper.verbose() and Helper.noisy(), ought to be public static methods. Making them static means that they
          are not candidates for use as builtin calls. That's ok because they are nto really intended to be used from rules (that's what debug is
          for). That also means we can call them from anywhewre in the Byteman code base without having to create a Helper instance.  I just
          realised (doh!) that this means we cannot have these methods simply call trace or traceln since they are both instance methods. These
          methods don't actually need to be instance methods since they don't refer to Helper fields. However, they need to be public instance
          methods because they are meant to be available as builtins.  So, what we need to do is to redefine trace and traceln so that they cal
          internal static methods Helper.dotrace and Helper.dotraceln and move the code in trace into dotrace and the code in traceln into
          dotraceln. All the other methods which use trace streams end up calling trace and traceln so this is the only change we need. 
          ? Another point is, for each isVerbose() a new PrintWriter is instantiated, it is by design or we can create only one per class where
          it is used or change all of the to them to the traceln method?
          Hmm, that's happening here because the print method needs to print a message and a stack trace. We can avoid that by providing a way
          of dumping a stacktrace in either verbose or noisy mode. 

          Rule.java

          ...

          } catch (TypeWarningException te) {

          checkFailed = true;

            if (Transformer.isVerbose()) {

              StringWriter stringWriter = new StringWriter();

              PrintWriter writer = new PrintWriter(stringWriter);

              writer.println("Rule.ensureTypeCheckedCompiled : warning type checking rule " + getName())

              te.printStackTrace(writer);

              detail = stringWriter.toString();

              System.out.println(detail);

            }

            ...

          So, what I suggest is that we provide two more methods  verboseStackTrace(Throwable)  and  noisyStackTrace(Throwable)  and then
          change code like the example above to this

            . . .
            } catch (TypeWarningException te) {
              checkFailed = true;
              if (Transformer.isVerbose()) {
                 Helper.verbose("Rule.ensureTypeCheckedCompiled : warning type checking rule " + getName());
                 Helper.verboseStackTrace(te);
              }
            . . .

          Methods verboseStackTrace() and noisyStackTrace() will try to lookup a trace with key "vrb" or "nzy". If no trace stream is found they will
          default to using System.out. They can both print the exception details by calling Throwable.printStackTrace(PrintStream).  Note that there
          is no need for noisyStackTrace() to be passed any bit field values. The stack trace message should always be preceded by a noisy
          message which identifies what type of trace is being generated.  
          The noisy trace that you suggested is awesome, most of times we want to trace only certain operations, for example to know
          if a rule was loaded or not. In this trace when enabled, it will print all varbose|debug logs or only the verbose|debug for the
          selected categories?
          My initial idea was that the flag fields should only limit output of noisy trace. So, when you enable org.jboss.byteman.verbose you will
          see

              debug|verbose  messages

          i.e. you will not see /any/ noisy trace.  When you enable org.jboss.byteman.noisy and select categories by setting

            org.jboss.byteman.noisy.categories="LOAD|INJECT"

          you will see messages in groups

            debug|verbose|noisy(INJECT)|noisy(LOAD)

          but you won't see messages in groups

            noisy(PARSE)|noisy(TYPE)|noisy(HELPER)|...

          If you set org.jboss.byteman.noisy but you leave property org.jboss.byteman.noisy.categories unset or else you set it to a value we
          cannot parse correctly then you will see messages in groups

            debug|verbose|noisy(X1)|...|noisy(Xn)

          for some set of categories X1, ..., Xn that we need to define.

          So, the point of the flags was not to filter the existing verbose messages but to ensure that switching on noisy trace does not swamp
          the user with messages for every single thing that Byteman is doing.  Of course, once we have the noisy trace mechanism in place
          we can change the level of any of the current verbose messages so that they are generated as noisy messages. 
          IF the maks is INVALID and the noisy trace is enabled, it can set the default set and print something like this in the logs:
          "THe noisy trace is enabled but no valid category was found, setting the default.". Also, it will be great if the default set of
          categories can be edited, makes sense?
          Yes, we will use the default categories if o.j.b.noisy/categories is unset or it contains text which does not identify one of the noisy category
          types.
          Ok, Filippe, I think the next thing for you to try is  clone the Byteman git repo  implement the new trace model  You don't actually need to modify
          all the existing internal tracing calls right away.

          Start by adding the static methods Helper.dotrace and Helper.dotraceln and redefine Helper.trace and Helper.traceln to call them.

          Next you need to implement Helper.verbose() and Helper.noisy() and also Helper.verboseStackTrace() and Helper.noisyStackTrace().

          Once you have done that you can try changing a few places where verbose messages are generated to make sure it correctly writes
          trace to System.out.

          The next step is to modify class Transformer so that it allows the verbose trace stream to be configured using a System property. This will
          allow you to check that verbose output can be redirected to a file.

          As a final step, you need to modify class Transformer so that it allows the noisy trace to be enabled and noisy categories to be configured.
          It is probably best to use a static long filed in class transformer as a bit mask to record which categories are enabled. You can then provide
          a method called Transformer.isNoisy(long) which can be used to test which categories are enabled by checking whether the corresponding
          bits in the field are set. That will allow you  to modify some Byteman code so it tests whether to generate a specific type of noisy trace message
          and if so calls noisy() to write it. You will also need to allow a tarce stream to be used to write the trace to a file.

          After that we will need to convert the existing verbose trace to use Transformer.isVerbose() and Helper.verbose()+Helper.verboseStackTrace().
          We will also need to start adding a whole load more verbose and also look at converting some of the other dump code (CFG or bytecode
          dumping) so it is controlled by the noisy category configuration.
          • 2. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
            adinn

            Filippe asks:

             

            Hello Andrew, a question, as we will create the dotrace and dotraceln as static we also will need to have the static methods openTrace and traceOpen as well, do you think better we create a new one as static or change it instead add a new?


            Oh, nice catch!


            traceOpen(Object, String)  is one of the documented builtin methods, part of the Helper convenience API that supports message tracing to stdout/stderr or to files. That means it has to be  a public instance method because Byteman only recognises public instance methods as builtin. That's the only reason why it has to be an instance method though -- the implementation does not actually reference 'this'. So, we can relocate the implementation into a static method and then make the instance method call the static method.


            What I suggest is that you redefine traceOpen so it calls a private static method dotraceOpen. Then define dotraceOpen so it does the work currently done by traceOpen. Thsi will allow you to change dotrace(Object,String)  and dotraceln(Object,String) so that they call dotraceOpen instead of openTrace.


            Also, just to explain why openTrace exists it's because I was inconsistent in how I named methods in one of the very early releases of Byteman. I moved the code for openTrace into traceOpen, making it part of the trace* builtin family. In order to avoid breaking existing scripts I made openTrace call traceOpen. It probably doesn't need to be kept since I doubt anything important relies on it but it doesn't do any harm to keep it. That explains why trace(Object, String) and traceln(Object, String) both call this method. When I wrote them this was what it was called. But that's also just a matter of legacy. You don't need to change openTrace. It will call its alias traceOpen and that will then call dotraceOpen.

            • 3. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
              filippe.spolti

              Thanks for the explanation.

               

              I'll do these changes then I back to you with the changes.

               

               

               

              Thanks.

              • 4. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                filippe.spolti

                Hello Andrew,

                 

                 

                What i done so far:

                 

                -> Created the method "public static boolean dotraceln" and changed the method traceln to call dotraceln method.

                -> Created the method "public static boolean dotrace" and changed the method trace to call dotrace method.

                -> Created the method "private static boolean doTraceOpen" and changed the traceOpen to call it.

                -> Inside the method dotrace and dotraceln I changed it "if (traceOpen(identifier)) {" to "if (doTraceOpen(identifier, message)) {"

                -> Changed the method "nextFileName' to static, since this method is now called inside doTraceOpen.

                -> Include a new method "public boolean trace(Object identifier, String message)"

                The following methods calls it:

                <code>

                    public void traceStack(String prefix, Object key, int maxFrames)

                    {

                        String stackTrace = formatStack(prefix, maxFrames);

                        trace(key, stackTrace);

                    }

                ...

                    public void traceAllStacks(String prefix, Object key, int maxFrames)

                    {

                         trace(key, formatAllStacks(prefix, maxFrames));

                    }

                   

                ...

                 

                    public void traceStackMatching(String regExp, boolean includeClass, boolean includePackage, String prefix, Object key)

                    {

                        String stackTrace = formatStackMatching(regExp, includeClass, includePackage, prefix);

                        trace(key, stackTrace);

                    }

                ...

                 

                    public void traceStackRange(String from, String to, boolean isRegExp, boolean includeClass, boolean includePackage, String prefix, Object key)

                    {

                        String stackTrace = formatStackRange(from, to, isRegExp, includeClass, includePackage, prefix);

                        dotrace(key, stackTrace);

                    }

                 

                 

                 

                You can check all changes here: https://github.com/bytemanproject/byteman/compare/master...spolti:BYTEMAN-294?expand=1

                 

                 

                Thanks.

                • 5. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                  adinn

                  Hi Filippe,

                   

                  Thanks for the update. It looks ok except for a couple of small details.

                   

                  The first problem is just a small coding error on your part:

                   

                  Inside doTrace you have made this change:

                   

                  -  if (openTrace(identifier)) {
                  +  if (doTraceOpen(identifier, message)) {
                  


                  Now, the original call:

                   

                  openTrace(identifier)


                  made a call to:

                   

                  openTrace(identifier, null)

                   

                  i.e. it passed null as the filename. That means that if there was not already a file associated with identifier then Helper would open a new file using whatever name nextFileName returns.


                  Your version is calling doTraceOpen(identifier, message) i.e. you are passing the message as the filename. If there is no file name associated with identifier then this will open a new file using the message as the filename. That's not a good idea as the message might be a stack trace! You need to change this line to:

                   

                  +  if (doTraceOpen(identifier, null)) {

                   

                  The second problem is a bit more subtle and needs some thinking about. In method closeTrace there are checks to ensure that the streams identified by "out" and "err" cannot be closed. You have extended this to also stop the streams identified by "dbg", "vrb" and "nzy" being closed.

                   

                     if (identifier == null ||
                  +                 identifier.equals("out") ||
                  -                identifier.equals("err")) {
                  +                identifier.equals("err") ||
                  +                // adding new trace levels categories
                  +                identifier.equals("dbg") ||
                  +                identifier.equals("vrb") ||
                  +                identifier.equals("nzy")) {
                               return false;
                  

                   

                  This worked in the original code because "out" and "err" were set up to identify System.out and System.err when class Helper was initialized. If you look at the end of the file you will see

                   

                      static {
                          traceMap.put("out", System.out);
                          traceMap.put("err", System.err);
                      }
                  

                   

                  So, the condition in traceClose ensures that these two streams can never be closed and then re-opened so they point to a file. It also means that we never attempt to close the two PrintStreams identified by "out" and "err" (closing either System.out and System.err would be a very bad thing).

                   

                  Now, I think we really want "dbg", "vrb" and "nzy" to direct output to System.out as the default destination. However, I think it would also be very useful if the users could redirect output for these trace streams to a file . So, that means we need to manage opening and closing of these streams in a different way.

                   

                  We only want to use a file for trace streams"dbg", "vrb" and "nzy"  if the user has explicitly called traceOpen  using one of these identifiers and a filename. If not then we want to direct output to System.out. Similarly, we only want to close a trace stream identified by one of these keys if it identifies a file that the user explicitly opened.

                   

                  So, we can do that as follows:

                   

                  In doTraceOpen we add an extra check when we find i) there is no existing entry and ii) the filename is null:

                   

                          synchronized(traceMap) { 
                              PrintStream stream = traceMap.get(identifier);
                              String name = fileName;
                              if (stream != null) {
                                  return false;
                              }
                              if (fileName == null) {
                  +                if (identifier.equals("dbg") || identifier..equals("vrb") || identifier.equals("nzy")) {
                  +                    return false;
                  +                }
                                  name = nextFileName();
                              }
                  

                   

                  This means that we will only ever insert an entry for these keys into the map when the user has asked for one. So, if the user has opened a stream for these keys then doTrace and doTraceln will find the stream and write to it. If the user has not opened a trace stream then when doTrace and doTraceln fail to find a stream in the map they will call doTraceOpen with null as the filename. The return value false will mean that they use System.out.

                   

                  That means we don't need to include your change traceClose to deal with trace streams"dbg", "vrb" and "nzy". We get sensible behaviour if we leave it as it is. If the user has opened a trace stream to a file with one of these 3 special names then traceClose will find the file stream, close it and remove it from the map returning true. If the user has no opened a trace stream then traceClose will not find an entry in the map so it will return false.

                   

                  Could you please go ahead and make these extra changes and then write  some Byteman rules to check that tracing still works ok.

                   

                  So, first you will need to check that when you call trace("dbg", "some message"), trace("vrb", "some other message") etc  output goes to System.out.

                   

                  Then you will need to check that when you call traceOpen("dbg", "debug.out"), traceOpen("vrb", verbose.out") etc that the calls to traceln end up adding messages to those files rather than to System.out.

                   

                  Finally make sure when you call traceClose("dbg"), traceClose("vrb") etc that output reverts back to System.out.

                  • 6. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                    adinn

                    Filippe asked on IRC

                     

                    another doubt, how exactly we will check for the identifier (vrb and nsy) in the verboseStackTrace and noisyStackTrace methods?

                     

                    I don't think you need to do anything special here


                    public static void verboseStackTrace(Throwable th)
                    {
                        doStackTrace("vrb", th);
                    }
                    
                    public static void noisyStackTrace(Throwable th)
                    {
                        doStackTrace("nzy", th);
                    }
                    
                    private static void doStackTrace(String id, Throwable th)
                    {
                      PrintStream ps;
                      synchronized (traceMap) {
                        ps = traceMap.get(id);
                        if (ps == null) {
                          ps = System.out;
                        }
                      }
                      th.printStackTrace(ps);
                    }
                    

                     

                    The synchronization is needed to make the get thread safe i.e. it avoids the possibility that another thread might be updating traceMap (under traceOpen or traceClose) when the caller is trying to read it.

                    • 7. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                      filippe.spolti

                      Hello Andrew,

                       

                      -> Could you please go ahead and make these extra changes and then write  some Byteman rules to check that tracing still works ok.

                      I think I can implement a test unit, do think it is a good idea?

                       

                      I'll also create some rules to test it in "production".

                       

                      I've made all the changes that your suggested. I think I need test it and make sure it is working so we go forward to the next changes.

                      • 8. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                        adinn

                        Hi Filippe,

                         

                        Do you have a repo with your updates in that I can review? or maybe even better James could do the review (since he might spot any flaws in my assumptions that got past you :-).

                         

                        Please write whatever tests you think you need to check this part is working ok and then we can go proceed to the next stage.

                         

                        regards,

                         

                         

                        Andrew DInn

                        • 9. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                          filippe.spolti

                          Hello,

                           

                          I commit the changes https://github.com/spolti/byteman/tree/BYTEMAN-294

                          The initial tests seems to work, using the following Rule:

                           

                          RULE  TestLog
                          CLASS ^br.com.hrstatus.utils.UserInfo
                          METHOD getLoggedUsername
                          AT EXIT
                          IF TRUE
                          DO
                            trace("Printing On Sysout");
                          
                            traceOpen("dbg");
                            trace("dbg","logging in a separated file.");
                            trace("dbg","[BYTEMAN-trace-dbg] user:  " + $!);
                            trace("dbg","[BYTEMAN-trace-dbg] Method Called: " + $METHOD);
                            trace("dbg","Closing File");
                            traceClose("dbg");
                          
                            trace("printing something on Systout");
                            trace("printing something on Systout again");
                            trace("printing something on Systout and over again");
                          
                          ENDRULE
                          

                           

                           

                          I have the following message in the logs:

                          19:37:48,503 INFO  [stdout] (default task-14) Printing On Sysout

                          19:37:48,504 INFO  [stdout] (default task-14) printing something on Systout

                          19:37:48,504 INFO  [stdout] (default task-14) printing something on Systout again

                          19:37:48,504 INFO  [stdout] (default task-14) printing something on Systout and over again

                           

                          And for each time the rule is fired a new file is created with the following content:

                          logging in a separated file.

                          [BYTEMAN-trace-dbg] user:  admin

                          [BYTEMAN-trace-dbg] Method Called: getLoggedUsername() java.lang.String

                          Closing File

                           

                           

                           

                          Regards,

                          Filippe

                          • 10. Re: Upgrade to Byteman (debug/verbose) tracing [BYTEMAN-294]
                            adinn

                            Hi Filippe,

                             

                            Apologies for the delay in returning to this task -- a combination of illness and tight deadlines for OpenJDK work means I was not able to review your fixes until yesterday.

                             

                            I have now pushed what is for the most part your commit to the main repo. However, I applied a few tweaks to clean things up a bit (here is the commit). The  most obvious difference to the version in your branch is that I regrouped the method definitions into 3 groups, reflecting what I finally realized is the logical organization:

                             

                            1. the original  Helper builtins (public instance methods) i.e. user API
                            2. methods for use by the Byteman agent (public static methods) i.e. internal agent API
                            3. the underlying implementation methods used by both the above (private static methods)

                             

                            So, when you compare it to your version it will look quite different but that's not really the case. Mostly things have just been moved around.

                             

                            The above grouping reveals the current structure the code (2 separate APIs over a common implementation) and clarifies the purpose of the methods in each API (static methods provide an internal API for use by the Byteman agent while instance methods provide a user API as Helper builtins). Once I saw this I realized that it made sense to keep doTrace and doTraceln as part of the private implementation and tweak the agent API as follows

                             

                              public static boolean out(String message)

                              public static boolean err(String message)

                              public static boolean verbose(String message)

                              public static boolean noisy(String message, int flags)

                             

                            which delegate to doTraceln(Object identfier, String message)

                             

                              public static void outTraceException(Throwable th)

                              public static void errTraceException(Throwable th)

                              public static void verboseTraceException(Throwable th)

                              public static void noisyTraceException(Throwable th, int flags)

                             

                            which delegate to method

                             

                              doTraceException(Object identifier, Throwable th)

                             

                            n.b. if these names don't look familiar then the implementations should as I just renamed your methods verboseStackTrace, noisyStackTrace and doStackTrace to verboseTraceException, noisyTraceException and doTraceException. This was to make it clear that they print a stack backtrace from an exception argument and are not related to the builtins which print a stack backtrace for the current thread..

                             

                            The internal agent API methods are almost complete but not quite:

                             

                            1. Methods out, err, outTraceException and errTraceException print their output unconditionally.
                            2. Methods verbose and verboseTraceException only print output when Transformer.isVerbose() returns true. So, they are now complete.
                            3. Methods noisy and noisyTraceException don't currently print anything. In fact the current versions don't even accept an int flags argument

                             

                            The noisy methods cannot really be completed until we define a set of trace classes and provide some bit field values which can be used i) to supply the flag values indicating which noisy trace classes a message or exception trace belongs to and ii) the set of trace classes enabled by the user. That is one of the two remaining tasks for you to follow up on.

                             

                            The out, err and verbose methods can be used straight away to replace existing print statements to System.out and System.err in the current agent code. All code that is guarded by if (Transformer.isVerbose()) needs to use the verbose methods. All other printing to System.out or System.err needs to use the out or err methods. That's the other task which is still left for you to do.

                             

                            n.b. there are two places where I made a change to your code which is worth mentioning (i.e. to add new functionality rather than just rename or reorganize things).

                             

                            Firstly, I extended the static block of code at the end of class Helper which initializes traceMap. As well as inserting entries for the "out" and "err" streams it now adds entries for dbg", "vrb" and "nzy". These trace streams all initially point to System.out. So, that means that by default debug, verbose and noisy output goes to the tty. Rule code can still redirect the output to a file using the builtins e.g. by calling traceClose("vrb") and then traceOpen("vrb", "myVerboseOutput.log"). That change also required me to add an extra check to traceClose. When it removes a trace stream from traceMap it has to check whether the PrintStream foudn in the map == System.out. In that special case it doesn't close the print stream. Otherwise all other output gets lost!

                             

                            Secondly, I decided to change the way trace file names are created -- this is only relevant when someone calls traceOpen(X) or traceOpen(X, null) i.e. when they don't supply a name for the output file. In that case a filename is constructed looking a bit like trace0000000000.log, trace0000000001.log etc. The new version still does that for most cases. However, if the trace stream identifier is "dbg", "vrb" or "nzy"  then it uses names like debug0000000001.log, verbose0000000000.log, noisy000000001.log etc.