Byteman 1.2.0 Bytes Deeper Into Your Code

The latest (1.2.0) version of Byteman is now available and it includes some new features which make it easier to specify where you want side effects to be injected to your code. These features are particularly useful for tracing but they are also of great benefit when it comes to using Byteman for its primary purpose which is fault injection testing.

Recap For Newcomers

For those of you who are new to Byteman or who did not see the earlier blog post about Monitoring the JVM using Byteman I'll just recap that Byteman is a bytecode injection tool which can be used to tweak application or JVM runtime code, adding side effects at specific points in any Java method. The injected code is not restricted to performing unintrusive actions like gathering statistics or printing trace output. It can access in scope objects and invoke public methods, changing either the application or the runtime state if it needs to. It can also short circuit the call to the modified method, forcing an immediate return or throwing an exception.

Byteman makes it easy to inject code which traces and verifies program execution and this is often all that is needed to test simple programs. However, in more complex tests the injected code will set up situations which exercise specific code paths by doing things like returning a spurious value, throwing an unexpected exception, inserting a timing delay, suspending one thread until another thread has completed some activity and so on. The most complex tests scenarios require multiple, highly specific interventions to propagate the effect of an initial fault. Byteman provides a simple, clear and expressive rule language based on Java which enables you to perform all these tasks. The programmer's guide is a good place to start if you want to full details of the language and how to use it to script test scenarios.

Back To The Program: A Sample Rule

Ok, so let's get back to those new features in 1.2.0 by introducing an example. I'm mostly going to stick to injecting trace code in the rest of this post but it should be obvious how the same features can be useful when defining rules which inject or propagate faults.

Here's one of the Byteman sample rules taken from the release which traces execution of the JVM Socket code.

RULE Socket trace bind
CLASS ^java.net.Socket
METHOD bind(SocketAddress)
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT EXIT
IF TRUE
DO traceStack("*** bind " + $this, 15)
ENDRULE

This rule is attached to CLASS Socket and targets METHOD bind(SocketAddress). It is triggered at EXIT from a call to bind and is fired unconditionally (i.e. the IF condition is TRUE) because we want to trace all calls to bind. The rule employs a HELPER class called StackTraceHelper which is provided in the sample library contained in the release. This helper class implements a method traceStack(String prefix, int depth) which can be called in the body of the rule as a built-in operation (i.e. with no target for the method call). Unsurprisingly, this helper method prints a prefix line and then dumps the stack. The depth argument provides an upper limit on the number of stack frames displayed.

The prefix in this case is constructed by concatenating the String literal "*** bind " with the parameter variable $this. The latter refers to the target instance for the bind call i.e. the socket being bound. The rule type checker identifies that $this is of type Socket, recognises that it is being consumed by a string plus operation where a String value is expected and automatically promotes $this to the correct type by inserting a toString() method invocation into the expression chain.

A helper method is used merely to simplify the rule, in this case wrapping up the code which traverses the stack and dumps details of each stack frame into a single call. The default helper provides, amongst other things, methods which can be used to synchronize independent threads, making it easy to orchestrate quite complex interactions in a multi-threaded application. Using custom helpers is particularly beneficial when scripting complex tests because many rules will perform common operations such as gathering statistics or detecting application-specific conditions and providing simple pre-canned calls keeps the rules clear.

It is perfectly possible to write code directly into the rule condition or action without using helper calls. Rule conditions and actions can call static methods or instance methods of accessible objects. For example, the following rule checks the port to which a socket has been bound and in one specific case prints a message to System.out then throws an exception

RULE Socket emergency!
CLASS ^java.net.Socket
METHOD bind(SocketAddress)
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT EXIT
IF $0.getLocalPort() == 999
DO System.out.println("Found the 999 call"),
  throw IOException("Call the police!")
ENDRULE

Note that this version must be invoked at EXIT because the call to getLocalPort() will only return the bound port after the call to bind has completed and is about to return.

So What's New In 1.2?

Now, the observant reader will have noticed that there is one small detail of the rule definition which I have not actually referred to yet: the ^ character preceding the class name. This bit of syntax is new with release 1.2.0 and although it comprises only a single character it makes the world of difference to the meaning of the rule.

The previous Byteman release contained a version of the 'Socket trace bind' rule without the ^ prefix and, in certain circumstances, this meant that bind calls were not traced. The problem is that in the Sun JVM there is a class called sun.nio.ch.SocketAdaptor which extends java.net.Socket. This method provides its own overriding implementation of bind(SocketAddress) and the overriding implementation does not make a call to super.bind(SocketAddress). The old version of the rule only gets injected into the bind method of class Socket. That means when a SocketAdaptor was bound the call to bind was not traced.

The ^ annotation means that the rule should apply to any implementation of method bind(SocketAddress) either on class Socket or a subclass which overrides the method. So, when using the Sun JVM the rule gets injected into class Socket and class SocketAdaptor. It also gets injected into abstract class com.sun.net.ssl.internal.ssl.BaseSSLSocketImpl and into any other application specific class which overrides Socket.bind(SocketAddress). So, with this new syntax there is no danger of missing a socket bind on the 999 port.

A Must-Have Override Example

Another example of the value of overriding rules is provided by the following rule taken from the sample scripts.

RULE FinalizeMonitor trace finalize
CLASS ^java.lang.Object
METHOD finalize
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT RETURN
IF TRUE
DO traceStack("finalizing " + $0, 1)
ENDRULE

This method traces every call to a finalize method and the ^ annotation ensures that it is injected into every overriding implementation of Object.finalize(). Note that without the ^ annotation the rule is useless because the garbage collector never calls finalize for objects whose class does not override Object.finalize()!

What About Interfaces?

So, that's one half of the extra functionality provided in Byteman 1.2.0, injection down class hierarchies. The other half is to allow injection through interfaces. All the examples so far have talked about injecting code into methods but when it comes to interfaces there are no methods to consider, only signatures. Here's an example taken from another of the sample rules.

  RULE ThreadMonitor trace Runnable.run
INTERFACE java.lang.Runnable
METHOD run()
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceRun($0)
ENDRULE

This rule is attached to a method of interface Runnable and is triggered by a call to the interface method run(). It uses a subclass of StackTraceHelper called ThreadMonitorHelper as its helper class. The built-in method traceRun prints the Runnable and its type and then prints details of the caller method which invoked run().

But what exactly does it mean to say "triggered by a call to the interface method run()"? Byteman identifies all classes which implement interface Runnable and injects the rule into the implementation of run() on these classes. So, for example, it will inject the rule into java.lang.Thread.run(), java.util.TimerThread.run() and so on.

Orthogonal? Composable?

Now, this is good because it means we don't have to write a rule for every class which implements Runnable. However, it is not quite enough to guarantee that every call to run() will be traced. For example, an application class which extends java.lang.Thread and provides its own implementation of run() will not be caught by this rule because it does not directly implement Runnable. The same applies to anonymous classes created to wrap an inline code block following a new expression such as

  Thread myWorker = new Thread() {
   public void run() { doBackGroundWork(); }
 };
 myWorker.start();

The anonymous class associated with myWorker does implement a run() method, overriding the implementation in Thread, but the class does not declare Runnable in its list of implemented classes. So, Byteman will not inject trace code into this overriding implementation and, hence, any call to myWorker.run() will not be traced.

The solution to this problem is simple. Just prefix the interface with the ^ annotation and injection is performed through the interface and down the resulting class hierarchies. The two new injection modes are orthogonal and composable.

Let's See That In Action

RULE ThreadMonitor trace Runnable.run
INTERFACE ^java.lang.Runnable
METHOD run()
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceRun($0)
ENDRULE

This version of the rule injects the rule code through the interface into implementing classes and down their subclass hierarchies into overriding implementations. It prints details of every call to and caller of Runnable.run() either internal to the JVM runtime or in application code. Here's a sample of the output when this rule is used to trace execution of the latest JBoss Application Server startup.

 starting server default 
========================================================================= 
 JBoss Bootstrap Environment 
 JBOSS_HOME: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT 
 JAVA: /usr/java/jdk1.6.0_14/bin/java 
 JAVA_OPTS: -Dprogram.name=run.sh -server -Xms600M -Xmx600M -XX:MaxPermSize=128m -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005 -Dorg.jboss.byteman.transform.all -javaagent:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar=listener:true,script:TraceRun.txt,boot:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar,boot:/home/adinn/jboss/byteman/trunk/install/sample/lib/byteman-sample.jar -Djava.net.preferIPv4Stack=true 
 CLASSPATH: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/bin/run.jar:/usr/java/jdk1.6.0_14/lib/tools.jar 
========================================================================= 
Listening for transport dt_socket at address: 5005 
 *** Thread run main java.lang.Thread  
   from VM runtime  
12:52:04,447 INFO [JBossASServerImpl] Server Configuration: 
     Bootstrap URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/bootstrap.xml 
     JBOSS_HOME URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/ 
     Common Base URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/common/ 
     Common Library URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/common/lib/ 
     Server Name: default 
     Server Base URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/ 
     Server Library URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/lib/ 
     Server Config URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/ 
     Server Home URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/ 
     Server Data URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/data/ 
     Server Log URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/log/ 
     Server Temp URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/tmp/ 
 *** Thread run Thread-3 java.lang.Thread  
   from VM runtime  
 *** Runnable run org.jboss.bootstrap.impl.base.server.AbstractServer$StartServerTask@1aecc3a org.jboss.bootstrap.impl.base.server.AbstractServer.StartServerTask  
   from java.lang.Thread.run at Thread.java:619  
12:52:04,462 INFO [AbstractServer] Starting: JBoss Server[6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r93729)] 
12:52:05,881 INFO [AbstractMCServerBase] Starting Microcontainer, Main bootstrapURL=file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/bootstrap.xml 
*** Thread run Timer-0 java.util.TimerThread  
   from VM runtime  
 *** Runnable run org.jboss.util.TimedCachePolicy$ResolutionTimer@1415727 org.jboss.util.TimedCachePolicy.ResolutionTimer  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Runnable run org.jboss.util.TimedCachePolicy@c0fc8e org.jboss.util.TimedCachePolicy  
   from org.jboss.util.TimedCachePolicy$ResolutionTimer.run at TimedCachePolicy.java:483  
12:52:07,243 INFO [VFSCacheFactory] Initializing VFSCache [org.jboss.virtual.plugins.cache.CombinedVFSCache] 
12:52:07,247 INFO [VFSCacheFactory] Using VFSCache [CombinedVFSCache[real-cache: null]] 
12:52:07,839 INFO [CopyMechanism] VFS temp dir: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/tmp 
12:52:07,866 INFO [ZipEntryContext] VFS force nested jars copy-mode is enabled. 
 *** Thread run ZipFile Lock Reaper java.util.TimerThread  
   from VM runtime  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
12:52:10,964 INFO [ServerInfo] Java version: 1.6.0_14,Sun Microsystems Inc. 
12:52:10,964 INFO [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_14-b08) 
12:52:10,964 INFO [ServerInfo] Java VM: Java HotSpot(TM) Server VM 14.0-b16,Sun Microsystems Inc. 
12:52:10,964 INFO [ServerInfo] OS-System: Linux 2.6.30.9-99.fc11.i686.PAE,i386 
12:52:10,965 INFO [ServerInfo] VM arguments: -Dprogram.name=run.sh -Xms600M -Xmx600M -XX:MaxPermSize=128m -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005 -Dorg.jboss.byteman.transform.all -javaagent:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar=listener:true,script:TraceRun.txt,boot:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar,boot:/home/adinn/jboss/byteman/trunk/install/sample/lib/byteman-sample.jar -Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/lib/endorsed  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 12:52:11,041 INFO [JMXKernel] Legacy JMX core initialized  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
  . . .  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
12:52:28,684 INFO [AbstractServerConfig] JBoss Web Services - Native Server 
12:52:28,684 INFO [AbstractServerConfig] 3.2.0.GA 
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Thread run SubscriptionWatchDog java.lang.Thread  
   from VM runtime  
 *** Runnable run org.jboss.ws.extensions.eventing.mgmt.SubscriptionManager$WatchDog@6b9547 org.jboss.ws.extensions.eventing.mgmt.SubscriptionManager.WatchDog  
   from java.lang.Thread.run at Thread.java:619  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
  . . .  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Thread run RMI TCP Accept-1090 java.lang.Thread  
   from VM runtime  
 *** Runnable run sun.rmi.transport.tcp.TCPTransport$AcceptLoop@7598d7 sun.rmi.transport.tcp.TCPTransport.AcceptLoop  
   from java.lang.Thread.run at Thread.java:619  
 *** Thread run RMI TCP Accept-0 java.lang.Thread  
   from VM runtime  
 *** Runnable run sun.rmi.transport.tcp.TCPTransport$AcceptLoop@19de1ba sun.rmi.transport.tcp.TCPTransport.AcceptLoop  
   from java.lang.Thread.run at Thread.java:619  
 *** Thread run RMI Reaper java.lang.Thread  
   from VM runtime  
 *** Runnable run sun.rmi.transport.ObjectTable$Reaper@185576 sun.rmi.transport.ObjectTable.Reaper  
   from java.lang.Thread.run at Thread.java:619  
 *** Thread run GC Daemon sun.misc.GC.Daemon  
   from VM runtime  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Thread run RMI TCP Connection(idle) java.lang.Thread  
   from VM runtime  
 *** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@132e9d5 java.util.concurrent.ThreadPoolExecutor.Worker  
   from java.lang.Thread.run at Thread.java:619  
 *** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@1231023 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler  
   from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886  
 *** Thread run RMI Scheduler(0) java.lang.Thread  
   from VM runtime  
 *** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@701c57 java.util.concurrent.ThreadPoolExecutor.Worker  
   from java.lang.Thread.run at Thread.java:619  
 *** Thread run RMI RenewClean-[127.0.0.1:47945] java.lang.Thread  
   from VM runtime  
 *** Runnable run sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread@1e88ea sun.rmi.transport.DGCClient.EndpointEntry.RenewCleanThread  
   from java.lang.Thread.run at Thread.java:619  
 *** Thread run RMI TCP Connection(idle) java.lang.Thread  
   from VM runtime  
 *** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@1c35be0 java.util.concurrent.ThreadPoolExecutor.Worker  
   from java.lang.Thread.run at Thread.java:619  
 *** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@9ba7c9 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler  
   from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886  
 *** Runnable run sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread@1e88ea sun.rmi.transport.DGCClient.EndpointEntry.RenewCleanThread  
   from java.lang.Thread.run at Thread.java:619  
 12:52:57,324 INFO [JMXConnectorServerService] JMX Connector server: service:jmx:rmi://127.0.0.1/jndi/rmi://127.0.0.1:1090/jmxconnector 
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Thread run ServerSocketRefresh org.jboss.remoting.transport.socket.SocketServerInvoker.ServerSocketRefresh  
   from VM runtime  
 *** Thread run AcceptorThread[ServerSocket[addr=/127.0.0.1,port=0,localport=4457]] org.jboss.remoting.transport.socket.SocketServerInvoker.AcceptThread  
   from VM runtime  
 *** Thread run secondaryServerSocketThread[0] org.jboss.remoting.transport.bisocket.BisocketServerInvoker.SecondaryServerSocketThread  
   from VM runtime  
 *** Thread run ServerSocketRefresh org.jboss.remoting.transport.socket.SocketServerInvoker.ServerSocketRefresh  
   from VM runtime  
 *** Thread run AcceptorThread[ServerSocket[addr=/127.0.0.1,port=0,localport=3873]] org.jboss.remoting.transport.socket.SocketServerInvoker.AcceptThread  
   from VM runtime  
 *** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask  
   from java.util.TimerThread.mainLoop at Timer.java:512  
 *** Thread run HDScanner java.lang.Thread  
   from VM runtime  
 *** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@1d64598 java.util.concurrent.ThreadPoolExecutor.Worker  
   from java.lang.Thread.run at Thread.java:619
*** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@9ba7c9 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler
   from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886

Where the Runnable is an instance of Thread the helper code prints the thread name and class. For non-threads it prints the Runnable instance and its class then details of the caller method. Notice that all the run calls associated with threads have no caller frame. This is because the thread stack is set up by the JVM with the run method as its entry point.

Most of the non-Thread Runnables are executed as the target of a dedicated thread and in these cases the call to run is made from Thread.run(). There are a few examples where the run method is invoked by pool threads, for example the last traced call shows a worker from the concurrent thread pool package being used to execute a Runnable which handles a TCP connection. In this case the call to run is made from the worker's execute method.