Comment 1 Andrew Clement 2010-09-10 11:10:32 EDT

I would suggest using the dump options in aop.xml to get out the before/after bytecode and comparing the two.  Hopefully the aspect isn't changing that method too much (you are weaving that method, yes?).

if you send me the before/after bytecode I'll take a look.  I've seen problems in the past with how switch statements are pulled apart and put back together by the bytecode toolkit we use, but thought I'd fixed all the issues.

Comment 2 Abraham Nevado 2010-09-10 13:18:16 EDT

Created attachment 178637 [details]
Before weaving and after conflictive class

Comment 3 Andrew Clement 2010-09-10 14:38:56 EDT

Ok - I can see the broken switch statement in the second case.  Here is a partial chunk.    This is the before method:

   32:	invokevirtual	#28; //Method com/arjuna/ats/arjuna/AtomicAction.status:()I
   35:	tableswitch{ //2 to 7
		2: 72;
		3: 112;
		4: 72;
		5: 112;
		6: 98;
		7: 98;
		default: 112 }
   72:	aload_0

observe the switch on (2) jumps to 72.

After weaving, it looks like this:

50:	invokevirtual	#28; //Method com/arjuna/ats/arjuna/AtomicAction.status:()I
   53:	tableswitch{ //2 to 7
		2: 90;
		3: 132;
		4: 90;
		5: 132;
		6: 116;
		7: 116;
		default: 132 }
   92:	aload_0

See the rewritten (2) now jumps to 90 which is not a valid location.  The other targets are similarly wrong (132 should be 134 and 116 should be 118).

I created some equivalent java:

aspect X {
  after(): execution(* A.m()) {
    System.out.println(thisJoinPoint.getArgs().toString());
  }
  before(): execution(* A.m()) {
    System.out.println(thisJoinPointStaticPart);
  }
}

interface LogNoi18n {
boolean isDebugEnabled(); 
void debug(String message);
String getString(String key);
}
class AtomicAction  {
  int status() { return 1; }
  int abort() { return 1; }
  int commit(int n) { return 1; }
}
class RollbackException extends RuntimeException {
  RollbackException(String s) {
    super(s);
  }
}

public class A {
public static void main(String []argv) {
  
 }
  static LogNoi18n logger;
  AtomicAction _theTransaction; 
  public void m() {
    if (logger.isDebugEnabled()) {
      logger.debug("TransactionImple.commitAndDisassociate");
    }
    if (_theTransaction!=null) {
      switch (_theTransaction.status()) {
      case 2:
      case 4:
        _theTransaction.abort();
        throw new RollbackException(logger.getString("inactive"));
      case 6:
      case 7:
        _theTransaction.commit(1);
         removeTransaction(this);
         return;
      case 3:
      case 5:
      default:
        switch (_theTransaction.commit(1)) {
           default:
        }
        break;
      }
    }
    new String("abc");
  }

  public static void removeTransaction(A o) {
  }
}

This attempts to mirror the problem precisely (with instruction offsets).  if you compile the code with the aspect commented out, you will get the same layout switch statement with the same jump offsets.  If you uncomment the aspect it will weave it exactly as the example does.  Unfortuntately when I do that, the switch statement is entirely correct in my case.  So something else is interfering in the larger example.  

To debug further we need to look at what happens for the InstructionSelect and TABLESWITCH/LOOKUPSWITCH bcel types and see when the offsets go wrong.

Comment 4 Andrew Clement 2010-09-10 14:57:37 EDT

I'm suspecting something around the miscomputation of the size of the switch statement on write.  If the size were miscomputed by 2 bytes then we'd probably see this problem - where the jump destinations were off by 2.  Looking around InstructionSelect.updatePosition.  Unfortunately I still can't recreate it though... then it would be trivial to fix...

Comment 5 Abraham Nevado 2010-09-10 15:29:47 EDT

I will try adding some additional traces when weaving the specific class... I will check if length is miscomputed and in affirmative case will try to figure out where... Keep updated.

Regards.

Comment 6 Abraham Nevado 2010-09-13 07:07:36 EDT

Hi Andy,

This one has been hard to debug however I believe we now what is going on. We modified InstructionList  in an ugly (only for debugging) way (we modified as well MethodGen to include method name in a threadLocal so we print debug info only for the conflictive method):

		/*
		 * Pass 2: Expand the variable-length (Branch)Instructions depending on the target offset (short or int) and ensure that
		 * branch targets are within this list.
		 */
		int offset = 0;
		for (InstructionHandle ih = start; ih != null; ih = ih.next) {
			if (ih instanceof BranchHandle) {
				int tmp= ((BranchHandle) ih).updatePosition(offset, maxAdditionalBytes);
				offset +=  tmp;

				String method = (String) MethodGen.th.get();
				if( method !=null && method.contains("commitAndDisassociate")){
					System.out.println("ABR-EUR: Pass 2: tmp:" + tmp + " AccOffset: " + offset);
					String message = "ABR-EUR: Pass 2:  dumping I at: "  + ih.getPosition() + "\n " + ih.toString();  
					System.out.println(message);
				}

			
			}
		}


And this are the traces we got:

12:47:15,812 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,813 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 26
12:47:15,813 INFO  [STDOUT]    26: ifeq[153](size3) -> aload_0
12:47:15,813 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,813 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 43
12:47:15,813 INFO  [STDOUT]    43: ifnull[198](size3) -> new 29
12:47:15,813 INFO  [STDOUT] ABR-EUR: lenght:39 fixedLength: 37 oldLength: 37 pos:53 padding: 2 offset: 0 max_offset: 18 returning:2
12:47:15,814 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:2 AccOffset: 2
12:47:15,814 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 53
12:47:15,814 INFO  [STDOUT]    53: tableswitch[170](size-2) -> aload_0(2, aload_0[42](size1) = {37})(3, aload_0[42](size1) = {77})(4, aload_0[42](size1) = {37})(5, aload_0[42](size1) = {77})(6, aload_0[42](size1) = {63})(7, aload_0[42](size1) = {63})
12:47:15,814 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 2
12:47:15,814 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 131
12:47:15,815 INFO  [STDOUT]   131: goto[167](size3) -> invokestatic 729
12:47:15,815 INFO  [STDOUT] ABR-EUR: lenght:66 fixedLength: 65 oldLength: 68 pos:142 padding: 1 offset: 2 max_offset: 18 returning:-2
12:47:15,815 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:-2 AccOffset: 0
12:47:15,815 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 142
12:47:15,815 INFO  [STDOUT]   142: tableswitch[170](size-2) -> new 60(2, new[187](size3) 40 = {87})(3, new[187](size3) 60 = {148})(4, new[187](size3) 40 = {87})(5, new[187](size3) 60 = {148})(6, goto[167](size3) -> goto -> 327 = {68})(7, goto[167](size3) -> goto -> 327 = {68})(8, new[187](size3) 60 = {148})(9, new[187](size3) 60 = {148})(10, new[187](size3) 60 = {148})(11, new[187](size3) 40 = {87})(12, new[187](size3) 60 = {148})(13, new[187](size3) 38 = {71})(14, new[187](size3) 38 = {79})
12:47:15,815 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,816 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 208
12:47:15,816 INFO  [STDOUT]   208: goto[167](size3) -> goto -> 327
12:47:15,816 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,816 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 249
12:47:15,816 INFO  [STDOUT]   249: ifnull[198](size3) -> aload_0
12:47:15,816 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,817 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 261
12:47:15,817 INFO  [STDOUT]   261: goto[167](size3) -> aload_1
12:47:15,817 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,817 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 271
12:47:15,817 INFO  [STDOUT]   271: ifnull[198](size3) -> aload_1
12:47:15,817 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,818 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 306
12:47:15,818 INFO  [STDOUT]   306: goto[167](size3) -> aload_0
12:47:15,818 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,818 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 331
12:47:15,818 INFO  [STDOUT]   331: goto[167](size3) -> goto -> 359
12:47:15,818 INFO  [STDOUT] ABR-EUR: Pass 2: tmp:0 AccOffset: 0
12:47:15,819 INFO  [STDOUT] ABR-EUR: Pass 2:  dumping I at: 341
12:47:15,819 INFO  [STDOUT]   341: goto[167](size3) -> invokestatic 729

As you can see AccOffset (accumulated Offset) is 0 at the end, so stage three is never executed:

		if (offset != 0) {

			/*
			 * Pass 3: Update position numbers (which may have changed due to the preceding expansions), like pass 1.
			 */
			index = count = 0;
			for (InstructionHandle ih = start; ih != null; ih = ih.next) {
				Instruction i = ih.instruction;
				ih.setPosition(index);
				pos[count++] = index;
				int tmp =i.getLength(); 
				index += tmp;
				
				String method = (String) MethodGen.th.get();
				}
		}

Although it should as far as although the accumulatedOffset is 0, there are some method which has been changed and require rearrangement.

So I propose the fix of taking into account not the accumulatedOffset to trigger Pass 3, but a new boolean flag that is set whenever a partial offset is different from 0.

I will attach the patch within the next minutes....

Regards.

Comment 7 Abraham Nevado 2010-09-13 07:17:48 EDT

Created attachment 178732 [details]
Lucierna's Proposed patch

Comment 8 Andrew Clement 2010-09-13 11:11:50 EDT

sounds reasonable.  But given what you now know, can you create a testcase for it?

Comment 9 Abraham Nevado 2010-09-15 11:48:02 EDT

Created attachment 178956 [details]
Repro Test Case

Thanks to the indispensable Andy's help who created the reduced class version....

Comment 10 Andrew Clement 2010-09-15 14:45:11 EDT

testcases are in, as is the fix.

Now we could recreate it, I took a copy of the code exhibiting the problem and reduced it to as small as possible such that it was still broken:

  public void m() {
    	switch (f.status()) {
    	case 1:
    		throw new RuntimeException("abc");
      	case 2:
    	  f.commit(1);
    	  return;
      	}
        switch (f.commit(1)) {
        case 1:
        	throw new RuntimeException();        
        }
  }

I added that as a testcase as well as the longer form.

Thanks for working hard on the fix/regression test.

(I also removed -1.6 from the options in the 1610 xml - some places where the tests run are not running a 1.6 VM)