• Ensure parity between method entry, exits, invokes and completes #4
• Report number of events traced
• Parse err logs for stack traces and report them
• Check for mangled traces, i.e. each line in trace file should contain only one trace-log, e.g. $$$,1,1,$$$,1,1 is mangled and not good

Premise

There has been a long-standing need to provide a way of specifying verbose configurations for a client java-agent, like Blinky Core, without changing the client's source code.

Configurations of a java-agent that are passed as cmdline arguments, like for Blinky Core, are too verbose to be specified on the command-line. A typical example of this is specifying+changing the classes to be excluded or (forcibly) included as targets of instrumentation. As such, instead of changing them on the java-agent's input arguments, Blinky Core has traditionally maintained+changed the values of such configurable lists/flags/properties in the Deputy.java source file.

Changing and managing configurable properties directly in Java source files is undesirable, as it would give the impression that these config-values are somehow integral to the implementation at hand, which they are not, and often cluter the project revision history.

Blinky Config

The goal with this module will be to provide a way specify and manage configurations for the various analysis modules in the Blinky infrastructure, starting with Blinky Core (for now).

Currrent mode-of-operations: As mentioned above the current mode of specifying configuration values is to do so by storing them in Java source files that are part of the compiled build, and changing the configurable properties in the source files directly.

Desired Change: Provide a way to store the config-values in a config file that is not a Java source code file.
Corollary: As such, we still want the actual configuration-values for the config'able properties of interest to be compiled into bytecode classfiles that are available to the rest of the code in the build-output.

Here is a list of features that will necessarily be a part of this change:

• This sub-module will enable the specification and modification of configuration values in a Yaml file, and not a Java source file.
• The sub-module will accept three inputs: (a) the Yaml file with the configuration values; (b) the classfile to which the configurable values will be compiled to; (c) the location of the compiled output where classfile is stored.
• This sub-module will compile the values in the Yaml config-file to generate/modifiy appropriate bytecode in the input Java bytecode classfile that can be used by the client java-agent's code to access user-provided configurations.
  • The idea behind converting a config file to a Java bytecode classfile is to give the analysis modules direct access to the configs through the class loader, thus avoiding the overhead in managing config-specific resource streams (for the client module, like Blinky core).
  • This will also ensure that parts of the configurations are bundled with the final Jar files of the client modules/projects.
  • Converting config files to classfiles implies that the configurations specified this way will be decided at compile-time; as such such configurations would be pre-defined and stable during runtime, i.e., they would not be configurable declaratively after the client module is packaged.
• These configurations will compiled to bytecode in a manner that will allow for overrides on the command line of the client module.

I'm currently analyzing a simple java program that recursively calls a function 4 times.
After the 4th time the function exists.

class Main{
  public static void main(String[] arg){
    RandomClass rc = new RandomClass(3);
    rc.run();
  }
}

class RandomClass{
  int value;
  public RandomClass(int number){
    this.value = number;
  }

  public void run(){
    if(this.value > 0){
      this.value--;
      this.run();
    }
  }
}

Original output
After running the postprocessing on it

If I compare the last two times we entered run() the line number is different (7 or 8). Is this because it enters and directly ends and because of that it is 8?

$[a-z]+$, ClassName, MethodName, ThreadID, LineNumber, StackDepth
$enter$, RandomClass, run()V, 1, 7, 5
$enter$, RandomClass, run()V, 1, 8, 6

• Keep the following modules as the default: core, util, trace-manager, tacoco; let's call it the default set
• Introduce three additional profiles in blinky's POM.xml (i.e. the parent project pom) for the following:
  • statik -- this adds statik to the default set.
  • diagnostics -- this adds diagnostics to the default set.
  • full -- this adds statik and diagnostics to the default set.

Following are the changes to the maven commands to invoke any of the three profiles:

• statik: mvn -P statik compile test package install
• diagnostics: mvn -P diagnostics compile test package install
• full: mvn -P full compile test package install

This is the source code of the class I used blinky to trace.
main.txt
Here are the documents needed to run the program.
stop_words.txt

pride-and-prejudice.txt

Below is a small part of the execution trace collected with blinky. I filtered all the execution out that have to do with thread 15.

['$$$', '67387', '15', '4875', '7', '910123336', '9393', '$enter$', 'NA\n']
['$$$', '67388', '15', '4875', '8', '1848651233', '9395', '$enter$', 'NA\n']
['$$$', '67389', '15', '4875', '8', '1848651233', '9397', '$enter$', 'NA\n']
['$$$', '67390', '15', '4876', '5', '1848651233', '9401', '$enter$', 'NA\n']
['$$$', '67391', '15', '4876', '6', '1848651233', '9397', '$enter$', 'NA\n']
['$$$', '67392', '15', '4876', '6', '1848651233', '9403', '$enter$', 'NA\n']

The call depth calculated by (blinky) is [7, 8, 8, 5, 6, 6]. So blinky seems to not instrument all the code causing gaps in the call depth. Is there away to make sure all the code is instrumented so we will make sure these gaps will not occur?
Or can it be that it is because of a different problem that we have gaps in our call depth? (I assume here that if a thread starts at a specific call depth it is not possible to go below that. So if our call depth starts at 7 then it shouldn't be able to go to 6 or lower.)

• Blinky Statik
  

The following error occurs when running a simple java program.

java.lang.VerifyError: Expecting a stackmap frame at branch target 43
Exception Details:
  Location:
    ClassThread.run()V @34: if_icmpge
  Reason:
    Expected stackmap frame at this location.
  Bytecode:
    0x0000000: 120a 1226 1228 2ac0 0004 b800 1eb8 0016
    0x0000010: 122a 2ac0 0004 b800 1eb8 002e 033c 1b11
    0x0000020: 03e8 a200 0984 0101 a7ff f612 302a c000
    0x0000030: 04b8 001e b800 2e12 0a12 2612 322a c000
    0x0000040: 04b8 001e b800 23b1
  Stackmap Table:
    append_frame(@30,Integer)
    chop_frame(@55,1)

    at Main.main(main.java:13)

When I remove the for loop in the run method from ClassThread then blinky doesn't have a problem running it. I small program with java 1.7. Also the problem only occurs when line execution events are turned on. What could be the problem?

public class Main {
    public static void main(String[] args){
        Thread t = new Thread(new ClassThread());
        t.start();
    }
}

public class ClassThread implements Runnable{

    @Override
    public void run() {
        for(int i = 0; i < 20; i++){
            System.out.println(i);
        }
    }
}

After instrumenting jEdit with Blinky we are seeing that it is actually instrumenting the methods, but for some reason are missing the actual Instruction Execution Event.

So the Instruction events and method declarations are there, but instruction Execution events are missing. Running on other applications seems to work fine. Here is the recorded trace jedit.txt.

The used command for running jEdit with blinky is:

java -Xbootclasspath/p:"/Users/kajdreef/Documents/Programmeren/Thesis/Projects/blinky/blinky-core/target/blinky-core-0.0.1-SNAPSHOT-jar-with-dependencies.jar"  -javaagent:"/Users/kajdreef/Documents/Programmeren/Thesis/Projects/blinky/blinky-core/target/blinky-core-0.0.1-SNAPSHOT-jar-with-dependencies.jar"='e,calldepth,frames' -jar build/jedit.jar > jedit.trc

Also I used the current version of blinky (0c47bba), but it seems to happen also with previous versions. Any idea what is the cause of this?

(@jycamus90 @CharlesFengY)

Time to move to Java 8.

[ERROR] Failed to execute goal org.codehaus.mojo:exec-maven-plugin:1.1.1:exec (default) on project blinky-diagnostics: Result of /bin/sh -c cd /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics && /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics/scripts/diagnose execution is: '1'. -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.codehaus.mojo:exec-maven-plugin:1.1.1:exec (default) on project blinky-diagnostics: Result of /bin/sh -c cd /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics && /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics/scripts/diagnose execution is: '1'.
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:212)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.apache.maven.plugin.MojoExecutionException: Result of /bin/sh -c cd /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics && /Users/Ku/Documents/uci/research/blinky/blinky-diagnostics/scripts/diagnose execution is: '1'.
    at org.codehaus.mojo.exec.ExecMojo.execute(ExecMojo.java:283)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    ... 20 more
[ERROR] 
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException

Any idea? mvn install fails only in blinky-diagnostics

When looking at this execution trace. When using 'grep' it shows that there are 123337 instruction execution events from those 45400 are '$complete$', but $invoke$ is called 45401, meaning one invocations is missing an complete.

Following subjects not working in blinky-diagnostics:

• styleEx.TheOne
• styleEx.noCommitment.NoCommitment

steps to reproduce:

• pull the repo...
• run mvn test to ensure that the code compiles and executes all the junit tests
• run mvn verify
• assuming that the code compiles and executes all the junit tests, the following error message should appear at the end of the run:

[INFO] styleEx.TheOne
[INFO] 🏃 running styleEx.TheOne with java
[INFO] Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: 0
[INFO]  at org.spideruci.analysis.diagnostics.subjects.styleEx.TheOne.main(TheOne.java:141)

[INFO] styleEx.noCommitment.NoCommitment
[INFO] 🏃 running styleEx.noCommitment.NoCommitment with java
[INFO] Exception in thread "main" java.lang.NullPointerException
[INFO]  at org.spideruci.analysis.diagnostics.subjects.styleEx.noCommitment.NoCommitment.load_plugins(NoCommitment.java:27)
[INFO]  at org.spideruci.analysis.diagnostics.subjects.styleEx.noCommitment.NoCommitment.main(NoCommitment.java:38)

Blinky Statik's ICFG computer seems to miss edges between a method invocation site and the first instruction of the method.

Change: added a new configuration option that allows adding multiple entry points in Statik

Usage:

• In the config file, use 'entrymethodsdb' option to specify a path to a database file generated from Tacoco (currently, only supporting database generated from Tacoco).

When I run blinky with xile,calldepth and xile,frames,calldepth on a project that is compiled with java 9 or 10 the following error occurs (full trace + example program can be found here:
):

java.lang.IllegalArgumentException
	at org.objectweb.asm.ClassReader.<init>(ClassReader.java:170)
	at org.objectweb.asm.ClassReader.<init>(ClassReader.java:153)
	at org.spideruci.analysis.statik.instrumentation.ClassInstrumenter.getClassReader(ClassInstrumenter.java:112)
	at org.spideruci.analysis.statik.instrumentation.ClassInstrumenter.instrument(ClassInstrumenter.java:23)
	at org.spideruci.analysis.dynamic.Blinksformer.instrumentClass(Blinksformer.java:64)
	at org.spideruci.analysis.dynamic.Blinksformer.transform(Blinksformer.java:47)
	at java.instrument/java.lang.instrument.ClassFileTransformer.transform(ClassFileTransformer.java:246)
	at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at java.instrument/sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:550)
	at java.base/java.lang.ClassLoader.defineClass1(Native Method)
	at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1007)
	at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)
	at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:801)
	at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:699)
	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:622)
	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:580)
	at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:185)
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:496)
	at java.base/java.lang.Class.forName0(Native Method)
	at java.base/java.lang.Class.forName(Class.java:375)
	at java.base/sun.launcher.LauncherHelper.loadMainClass(LauncherHelper.java:654)
	at java.base/sun.launcher.LauncherHelper.checkAndLoadMain(LauncherHelper.java:551)
instrumentation failed for org/spideruci/Hello

When I modified the asm-debug-all dependency from version 5.0 to 6.0_BETA, I am able to run blinky on at least java 9, but not java 10 yet.

So the following configuration works after changing to ASM 6.0_BETA:

java version "9.0.4"
Java(TM) SE Runtime Environment (build 9.0.4+11)
Java HotSpot(TM) 64-Bit Server VM (build 9.0.4+11, mixed mode)

But this one does not:

java version "10.0.1" 2018-04-17
Java(TM) SE Runtime Environment 18.3 (build 10.0.1+10)
Java HotSpot(TM) 64-Bit Server VM 18.3 (build 10.0.1+10, mixed mode)

When running the following command:

man test -P statik

The following the blinky-statik module fails.
[INFO] Blinky Statik 0.0.1-SNAPSHOT ....................... FAILURE [ 0.012 s]

The following artifact is missing org.spideruci.analysis.statik.controlflow:jump:jar:1.0-SNAPSHOT, see error message below.

[ERROR] Failed to execute goal on project blinky-statik: Could not resolve dependencies for project org.spideruci.analysis.statik:blinky-statik:jar:0.0.1-SNAPSHOT: Could not find artifact org.spideruci.analysis.statik.controlflow:jump:jar:1.0-SNAPSHOT -> [Help 1]

org.spideruci.analysis.util.ErrorLogManager, org.spideruci.analysis.util.MyAssert, org.spideruci.analysis.util.Constant, and org.spideruci.analysis.util.ByteCodePrinter are present in both blinky-core and blinky-util. As a result, calls to methods in these classes from Blinky Core fail and as such, seemingly causing an abort of the load-time return of the instrumented classes in Blinksformer#instrumentClass(...) method, particularly due to a call to ErrorLogManager#logClassTxStatus.

TODOs

ErrorLogManager
This is only being referenced from blinky-core, and has a dependency on REAL_OUT and REAL_ERR in the Profiler class in Blinky. As such do the following:

• delete org.spideruci.analysis.util.ErrorLogManager from both Blinky Core and Util
• Re-package it under org.spideruci.analysis.logging.ErrorLogManager

ByteCodePrinter
This is only being referenced from blinky-core, but has no other dependency on Blinky Core, and it can be potentially used for purposes outside the scope of Blinky Core. As such do the following:

• delete org.spideruci.analysis.io.ByteCodePrinter from Blinky Util
• delete org.spideruci.analysis.util.caryatid.ByteCodePrinter from Blinky Util
• move org.spideruci.analysis.util.ByteCodePrinter from Blinky Core to Blinky Util

MyAssert and Contants
They were created with a much more global scope in mind and MyAssert in particular is used by core, util, trace-manager and diagnosis. Thus, the following actions are to be taken:

• move org.spideruci.analysis.util.MyAssert from Blinky Core to Blinky Util
• move org.spideruci.analysis.util.Constants from Blinky Core to Blinky Util

What: With this change - this commit and the commit before this,
we are now able to weave multiple executable blocks that
implement some form of static analysis.

Why: This basically sets up different analyses that devs may want
to implement and execute on the same code/system under analysis.
Essentially, no more changing the main method in Statik class to
change the kind of static analysis to be run on the code under
analysis ... All changes to the config file.

Details:

• AnalysisBlock Class
  Specifically, all analysis code will be implemented in classes that
  extend the AnalysisBlock class in the org.spideruci.analysis.statik.blocks
  package. This class has an execute method that is required by
  the sub-classes to implement. This method takes as input an instance
  of the ClassGraphManager. This gives all analysis-block access
  to the call graph of code/system under analysis. All these classes
  are implemented under the package org.spideruci.analysis.statik.blocks.

• Specifying AnalysisBlocks in Config File
  The AnalysisBlocks are executed when they are specified in the con-
  fig file. If the blocks are to be considered for execution, they
  should be prepended with the dollar sign ($). Further, they must
  be specified with the fully qualified names of the sub-class (i.e.,
  with the package name) that is implementing the AnalysisBlock
  class.

• The Executor Loop in Statik.java
  An exec loop in Statik will create an instance for each sub-class
  specified in the Config file. The execute method on each of those
  instances will then be executed, while passing along the Call Graph
  manager of the code under analysis to each execute invocations.

Blinky currently does not support nor test the instrumentation of the InvokeDynamic byte-code instruction, nor does it account for the specific changes/features that came in with Java 8 like default methods in Interfaces or Lambdas. Below is a preliminary list of things that need to to accounted for with this regard.

• Invokedynamic bytecode instruction (!!!)
• Default methods in Interfaces
• Lambdas
• Method Handles
• java.util.Stream
  • getStream.parallel()
  • getStream.collect()
  • stream().reduce(...)
• java.util.function

Note that InvokeDynamic and Java 8 support are two distinct things to cater for and support. Supporting Invokedynamic does not imply that all new relevant features in Java 8 have been supported or tested.

Below is a 'grep' of all the instruction execution events from an execution trace generated by blinky. It seems like there is an offset for the call depth by 1, because the call depth should start at 2 instead of 1. I assume.

$$$,1,1,0,2,C,3,$enter$,NA
$$$,2,1,5,3,856419764,5,$enter$,NA
$$$,3,1,5,3,856419764,6,$exit$
$$$,4,1,5,3,856419764,7,$enter$,NA
$$$,5,1,5,4,856419764,9,$enter$,NA
$$$,6,1,6,5,856419764,11,$enter$,NA
$$$,7,1,6,6,856419764,13,$enter$,NA
$$$,8,1,6,7,856419764,15,$enter$,NA
$$$,9,1,6,7,856419764,16,$exit$
$$$,10,1,7,2,C,4,$exit$

(Done with the latest version (41c3fd8) of blinky)

Proposed API for CallGraphManager:

• Add entry points
• Method Exists?
• Get method's callers
• Get method's calls
• Get bottom-up topology
• Get DFS iteration
• Get BFS iteration
• Print Graph

Does blinky provide a blacklist to filter out the instrument of some dependencies? Could you please tell how should I specify the white/black list for blinky?