Spring AOP randomly fails when advising JpaRepository

[gkgeorgiev]

I am trying to intercept JpaRepository methods in my app, but for whatever reason, if I restart my Spring Boot app several times, then one of the aspects doesn't always work.

The advice onBusinessRelationshipSaveAll sporadically fails, while onBusinessRelationshipDeleteAll seems to be always working.

I've pushed a simplified version of my app here https://github.com/gkgeorgiev/aop-demo.

Be aware that you might have to restart the app 3-4 times since the behavior is unpredictable.

I've also debugged and tried to understand the proxy creation, and I noticed that sometimes in the list of advisors, the pointcut advisor with expression execution(* com.example.demo.BusinessRelationshipRepository.save*(..)) is missing for whatever reason.

I initially created Stackoverflow question but the more I debugged the more I think there's a problem with the Spring aspects mechanism.

P.S. If you are using IntelliJ .... I've created requests.http inside the test folder, to test/reproduce the problem.

C:\dev\git\aop-demo>java -version
openjdk version "11.0.12" 2021-07-20
OpenJDK Runtime Environment Temurin-11.0.12+7 (build 11.0.12+7)
OpenJDK 64-Bit Server VM Temurin-11.0.12+7 (build 11.0.12+7, mixed mode)

[kriegaex]

FWIW, cloning the example repository I can reproduce the issue, even though I have no good idea what may cause it. Logic implies that in some way an order of events within the Spring framework could be a reason. Is there anything happening asynchronously? Is there any piece of code relying on something being cached which is not (yet)? I am just guessing here.

[kriegaex]

P.S. If you are using IntelliJ .... I've created requests.http inside the test folder, to test/reproduce the problem.

I simply converted your JSON PUT request into Java code, replacing the driver application as follows, so you can just run it and set breakpoints wherever you like. It will also terminate automatically after execution:

package com.example.demo;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ConfigurableApplicationContext;

import java.util.List;

import static com.example.demo.RelationshipTypeEnumDto.CUSTOMER;
import static com.example.demo.RelationshipTypeEnumDto.VISIBLE;

@SpringBootApplication
public class DemoApplication {

  public static void main(String[] args) {
    try (ConfigurableApplicationContext context = SpringApplication.run(DemoApplication.class, args)) {
      OrganisationController organisationController = context.getBean(OrganisationController.class);
      List<BusinessRelationshipDto> dtos = List.of(
        createDto(VISIBLE, "_7JkS2Nty-l2S0emLjV_kW0"),
        createDto(VISIBLE, "_-Phh-cdigrk_TICVqXRv8H"),
        createDto(CUSTOMER, "_fLdHz86UEeujNIM3TF9ZaQ"),
        createDto(VISIBLE, "_fLdH1c6UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_fLdH1M6UEeujNIM3TF9ZaQ"),
        createDto(VISIBLE, "_fLdvLs6UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_fLdHyc6UEeujNIM3TF9ZaQ"),
        createDto(VISIBLE, "_fLdHys6UEeujNIM3TF9ZaQ"),
        createDto(VISIBLE, "_fLdH0c6UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_fLdvLc6UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_rr_H_Q_2oYFNapCL9RQiDC"),
        createDto(VISIBLE, "_fLdH0M6UEeujNIM3TF9ZaQ"),
        createDto(VISIBLE, "_fLdHxs6UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_ITufRSYr0yOOnpnzJwMcdq"),
        createDto(VISIBLE, "_fLdHw86UEeujNIM3TF9ZaQ"),
        createDto(CUSTOMER, "_fLdHws6UEeujNIM3TF9ZaQ")
      );
      organisationController.putBusinessRelationships(dtos);
    }
  }

  private static BusinessRelationshipDto createDto(RelationshipTypeEnumDto type, String uuid) {
    BusinessRelationshipDto dto;
    dto = new BusinessRelationshipDto();
    dto.setType(type);
    dto.setUuid(uuid);
    return dto;
  }

}

---

Update: It also makes sense to add an unconditional log output at the beginning of each aspect advice method and also do a null check for the relationships* collections in order to avoid ugly exceptions:

package com.example.demo;

import java.util.Collection;
import lombok.extern.java.Log;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;

@Aspect
@Log
@Component
class BusinessRelationshipAspect {

  private final BusinessRelationshipRepository relationshipRepository;

  @Autowired
  public BusinessRelationshipAspect(final BusinessRelationshipRepository relationshipRepository) {
    this.relationshipRepository = relationshipRepository;
  }

  @Around("execution(* com.example.demo.BusinessRelationshipRepository.save*(..))")
  public Object onBusinessRelationshipSaveAll(final ProceedingJoinPoint joinPoint) throws Throwable {
    log.info("### " + joinPoint);
    if (!(joinPoint.getArgs()[0] instanceof Collection))
      throw new RuntimeException("Supporting JMS events messaging for business relationships only for Collections"); //NOSONAR
    final Collection<BusinessRelationshipEntity> relationshipsAfter = (Collection<BusinessRelationshipEntity>) joinPoint.proceed();
    if (relationshipsAfter != null) {
      for (final BusinessRelationshipEntity newRel : relationshipsAfter)
        log.info("Save " + newRel.getUuid());
    }
    return relationshipsAfter;
  }

  @Around("execution(* com.example.demo.BusinessRelationshipRepository.deleteAll(..))")
  public Object onBusinessRelationshipDeleteAll(final ProceedingJoinPoint joinPoint) throws Throwable {
    log.info("### " + joinPoint);
    if (!(joinPoint.getArgs()[0] instanceof Collection))
      throw new RuntimeException("JMS event messaging for deleting business relationship supported only for Collections"); //NOSONAR
    final Collection<BusinessRelationshipEntity> relationships = (Collection<BusinessRelationshipEntity>) joinPoint.proceed();
    if (relationships != null) {
      for (final BusinessRelationshipEntity rel : relationships)
        log.info("Delete " + rel.getUuid());
    }
    return relationships;
  }

}

---

Update 2: I created PR gkgeorgiev/aop-demo#1 for everyone's convenience. I hope it will speed up triage.

[gkgeorgiev]

FWIW, cloning the example repository I can reproduce the issue, even though I have no good idea what may cause it. Logic implies that in some way an order of events within the Spring framework could be a reason. Is there anything happening asynchronously? Is there any piece of code relying on something being cached which is not (yet)? I am just guessing here.

I also have the same impression, but while debugging I couldn't see some key cache initializations steps :/

[gkgeorgiev]

In addition to the mentioned above, I found out that an advice with such annotation always intercept all methods @Around("target(com.example.demo.BusinessRelationshipRepository)")

Thx

[apdya]

after debug with this demo, i found this may be a bug of aspectj-weaver, and this bug has to do with bridge method.

[sbrannen]

Hi @apdya,

Thanks for debugging it.

Can you please provide further details on your findings (such as the call stack into aspectj-weaver and which part of aspectj-weaver appears to contain the bug)?

[kriegaex]

after debug with this demo, i found this may be a bug of aspectj-weaver, and this bug has to do with bridge method.

That is just an unfounded claim without any proof. If you want me - I happen to be the current AspectJ maintainer - to take action and possibly fix an existing bug, I need a little more than just that.

[apdya]

Sorry for the late reply. Here are some more details about what I found. @sbrannen, and hope you can figure it out @kriegaex

call stack

where the bug maybe in

org.aspectj.weaver.ResolvedType

/**
 * Looks for the first member in the hierarchy matching aMember. This method differs from lookupMember(Member) in that it takes
 * into account parameters which are type variables - which clearly an unresolved Member cannot do since it does not know
 * anything about type variables.
 */
public ResolvedMember lookupResolvedMember(ResolvedMember aMember, boolean allowMissing, boolean eraseGenerics) {
	Iterator<ResolvedMember> toSearch = null;
	ResolvedMember found = null;
	if ((aMember.getKind() == Member.METHOD) || (aMember.getKind() == Member.CONSTRUCTOR)) {
		// toSearch = getMethodsWithoutIterator(true, allowMissing, !eraseGenerics).iterator();
		toSearch = getMethodsIncludingIntertypeDeclarations(!eraseGenerics, true);
	} else if (aMember.getKind()==Member.ADVICE) {
		return null;
	} else {
		assert aMember.getKind() == Member.FIELD;
		toSearch = getFields();
	}
	while (toSearch.hasNext()) {
		ResolvedMember candidate = toSearch.next();
		if (eraseGenerics) {
			if (candidate.hasBackingGenericMember()) {
				candidate = candidate.getBackingGenericMember();
			}
		}
		// OPTIMIZE speed up matches? optimize order of checks
		if (candidate.matches(aMember, eraseGenerics)) {
			found = candidate;
			break;
		}
	}

	return found;
}

explanation

JpaRepository (spring-data-jpa-2.5.7) override method saveAll from CrudRepository and change the return type to List from Iterable, so JpaRepository have two method with same method signature, one is List saveAll(Iterable entities), another is bridge method Iterable saveAll(Iterable entities).

Back to ResolvedType#lookupResolvedMember, this method only looks for the first member in the hierarchy matching aMember, but toSearch contains both two method, and toSearch is not sorted. if List saveAll(Iterable entities) is before Iterable saveAll(Iterable entities) SignaturePattern#matches will return true, advice will matched. otherwise SignaturePattern#matches will return false, because Iterable saveAll(Iterable entities) is a bridge method.

in this case advice matched

in this case advice matched failed

[sbrannen]

@apdya, thanks for providing the details!

@kriegaex, I see that you're working on this (eclipse-aspectj/aspectj@17fa416). Please keep us posted on your progress. Thanks!

[kriegaex]

The fix seems easy enough, but I am unfamiliar with the part of the AspectJ code it occurs in and what side effects the fix might have. No AspectJ tests are breaking, but that might be due to a gap in testing that specific case.

Locally, I have tried several kinds of ways to reproduce this problem with plain AspectJ (no Spring involved, specifically no Spring AOP), both using compile-time and load-time weaving, both with hard-coded interface implementations and dynamic JDK proxies like in the example here. I am unable to reproduce the problem, no matter how often I repeat the tests. I see the bridge method in toSearch, but it is never found first. I can only reproduce it, if I manipulate the code to specifically select bridge methods, which is obviously wrong and the opposite of the fix to specifically exclude them. I always feel better if I have a regression test first, but I will not add a Spring dependency to AspectJ just to reproduce it within the AspectJ test suite.

It seems that the entry point org.springframework.aop.aspectj.AspectJExpressionPointcut#getShadowMatch, calling interface method org.aspectj.weaver.tools.PointcutExpression#matchesMethodExecution, implemented by org.aspectj.weaver.internal.tools.PointcutExpressionImpl#matchesMethodExecution, is occurring in a situation that is hard to reproduce.

[kriegaex]

I finally managed to reproduce the problem with an ASM-modified class file (but not with AspectJ on-board means). A regression test is in place, the bugfix was merged and you can re-test it with or without Spring. Please use 1.9.21-SNAPSHOT, even though I am actually considering to publish a 1.9.20.1 bugfix release, because 1.9.20 was just released last week and Java 21 support is not due before JDK 21 and the corresponding Eclipse Java Compiler changes have been released.

<repositories>
    <repository>
        <id>ossrh-snapshots</id>
        <url>https://oss.sonatype.org/content/repositories/snapshots</url>
        <releases>
            <enabled>false</enabled>
        </releases>
        <snapshots>
            <enabled>true</enabled>
            <updatePolicy>always</updatePolicy>
        </snapshots>
    </repository>
</repositories>

@gkgeorgiev, @apdya, please both retest and provide feedback here.

[kriegaex]

@apdya, let me not forget to thank you for doing a great job 🙏, digging into this and documenting your debug findings concerning the bridge method issue. That was key to me being able to see what was happening and improve something for Spring users, despite the fact that the problem was irreproducible for me in plain AspectJ, no matter what I tried. But certainly, a situation is imaginable in which AspectJ would exhibit the same behaviour. Being sensitive to the order of found methods like this, was not good for sure, which I acknowledged by classifying the issue as a bug in the AspectJ issue & PR pair.

[sbrannen]

Thanks for fixing the issue in AspectJ, @kriegaex! 👍

Much appreciated.

In light of that, I am closing this issue.

---

side note: we noticed a regression in AspectJ 1.9.20 in our test suite, so I'll raise an issue for that too, which you can hopefully address in AspectJ 1.9.20.1.

[kriegaex]

@sbrannen, you could show your appreciation by also merging my fix for a Spring bug, PR #28322. 😉

[sbrannen]

@sbrannen, you could show your appreciation by also merging my fix for a Spring bug, PR #28322. 😉

Indeed. I'll take another look!

[kriegaex]

I am disappointed that nobody provided re-testing feedback, even though this problem only affected Spring AOP, not even AspectJ proper. The lack of feedback kept me withholding the AspectJ 1.9.20.1 bugfix release for longer than necessary. Anyway, today I released the new version. Enjoy.

[gkgeorgiev]

I am disappointed that nobody provided re-testing feedback, even though this problem only affected Spring AOP, not even AspectJ proper. The lack of feedback kept me withholding the AspectJ 1.9.20.1 bugfix release for longer than necessary. Anyway, today I released the new version. Enjoy.

I apologize that I can't re-test it. In the meantime I have changed my job and no longer have access to the old projects, but I do appreciate your effort!

[joseandres1987]

I am disappointed that nobody provided re-testing feedback, even though this problem only affected Spring AOP, not even AspectJ proper. The lack of feedback kept me withholding the AspectJ 1.9.20.1 bugfix release for longer than necessary. Anyway, today I released the new version. Enjoy.

It took some time, but it works well now! Thanks a lot for this fix, highly appreciated!