Four AOP Recipes: Logging, Permissions, Rate Limiting, Caching

bee2026-10-0868 min read0 views

Four copy-ready aspects: annotation-driven audit logging, permission checks, a simple token-bucket limiter and caching — each with full code and the traps involved.

#AOP

1 / 111

Section

0. The 30-second version

2 / 111

The last two articles covered "how to write a pointcut" and "how the proxy is built". This one does a single job: turn that theory into three aspects you could paste into your project tomorrow — audit logging, timing, and authorization. Their shared pattern fits in one sentence: a custom annotation declares "which method wants this capability", and an aspect implements "how that capability is delivered". Business code gains one annotation line, the rule lives in one class, and changing it once changes it everywhere.

3 / 111

You will meet those five terms again and again here, so pin them to everyday scenes once and for all. A join point is one invocation actually happening — the parcel being scanned on the conveyor; a pointcut is the sorting rule deciding which chute each parcel takes; advice is the extra operation a worker performs beside the chute, like the button guard you gain when putting a case on a phone; an aspect is the machine packaging "rule + operation" together; and weaving is bolting that machine onto the conveyor — rather like going through security: the passenger (your business code) is unchanged, yet everyone must pass the same gate before departure.

4 / 111

类比｜Analogy

an onion explains the order when several aspects stack. One call is an onion: the outermost skin meets the knife first but is peeled last; the innermost skin arrives latest yet peels off first, and the core is the target method. So the @Order(1) logging aspect enters first and leaves last, the @Order(2) timing aspect enters second and leaves second-to-last, and the log's "total time" is always a hair larger than what the timing aspect measured itself — the difference is the shell's own overhead. Whoever sits closest to the core finishes earliest: that one line answers every ordering question.

5 / 111

类比｜Analogy

airport security explains why the authorization aspect blocks at the door. A @Before permission check is the gate: bad credentials (a missing permission code) are refused on the spot, the person never reaches the boarding area, and no downstream cost accrues. But its position matters — put it too far out (before the logging aspect) and even refused travellers get logged as "cleared"; put it too far in (inside the transaction) and you print the boarding pass, assign the seat, start the engines, and only then say the document is invalid, having burned a database connection for nothing. That is exactly the reasoning behind the @Order table in Section 6.

6 / 111

Diagram

Figure · Chapter map: which advice for which job

7 / 111

After this section you should be able to answer three questions:

8 / 111

If I need both the return value and the elapsed time, why is @Around the only option — and when all I want is "block it if invalid", why is it the wrong choice?
With three aspects hitting one method, how should @Order be arranged, and what kind of "everything works, semantics are wrong" incident does a bad arrangement cause?
How exactly should try/catch be written inside around advice so you do not accidentally eat the transaction's ability to roll back?

9 / 111

Section

1. The universal pattern: annotation + aspect

10 / 111

The previous sections explained the machinery; this one serves the dishes. All four aspects share one structure: use a custom annotation to declare "which methods need this capability", then use an aspect to implement "how that capability is actually done".

11 / 111

Why is this the most elegant combination? Because it cleanly separates intent from implementation:

12 / 111

Business code gains only an annotation, and the meaning is self-explanatory: @OpLog("delete user") clearly means an audit log
The aspect is written once and attaches to the annotation, so every method that needs it gets the capability for free
The two couple only through the annotation — swap the implementation and the business code does not change a single character

13 / 111

Here is what the annotation looks like. A custom annotation centers on two meta-annotations, "target" and "retention":

14 / 111

Code

Codejava

package com.example.anno;import java.lang.annotation.*;@Target(ElementType.METHOD)          // attaches to methods@Retention(RetentionPolicy.RUNTIME)  // readable at runtime, so the aspect can see it@Documentedpublic @interface OpLog {    String value() default "";       // description, e.g. "delete user"    boolean recordArgs() default true;   // whether to log the arguments}

Notes

@Target(METHOD) restricts it to methods and prevents misuse on classes or fields
@Retention(RUNTIME) is mandatory: the aspect reads the annotation reflectively at runtime, and CLASS retention would hide it
value() has a default, so both @OpLog and @OpLog("delete user") are valid

Tip: put the four annotations in one anno package for unified management. Prefer verb-phrase names (OpLog / RequirePerm) so it reads as "what this annotation requires", clearer than names like LogAnnotation.

15 / 111

Section

2. Aspect one: audit logging with @OpLog

16 / 111

Requirement: record who called what method, with which arguments, what was returned, and how long it took. This is exactly @Around territory — only it can access both inputs and return value.

17 / 111

Diagram

18 / 111

Code

Codejava

package com.example.aspect;import com.example.anno.OpLog;import org.aspectj.lang.ProceedingJoinPoint;import org.aspectj.lang.annotation.*;import org.aspectj.lang.reflect.MethodSignature;import org.slf4j.*;import org.springframework.stereotype.Component;import org.springframework.web.context.request.*;import jakarta.servlet.http.HttpServletRequest;import java.util.Arrays;import java.util.UUID;@Aspect@Componentpublic class OpLogAspect {    private static final Logger log = LoggerFactory.getLogger(OpLogAspect.class);    @Around("@annotation(opLog)")    public Object around(ProceedingJoinPoint pjp, OpLog opLog) throws Throwable {        // Generate a traceId to tie together every log of this request        String traceId = UUID.randomUUID().toString().substring(0, 8);        MDC.put("traceId", traceId);        long start = System.nanoTime();        String op = opLog.value().isEmpty()                ? ((MethodSignature) pjp.getSignature()).getMethod().getName()                : opLog.value();        try {            Object result = pjp.proceed();            if (opLog.recordArgs()) {                log.info("[{}] op={} args={} result={} took={}ms user={}",                        traceId, op, Arrays.toString(pjp.getArgs()), result,                        (System.nanoTime() - start) / 1_000_000, currentUser());            }            return result;        } finally {            MDC.clear();   // mandatory: reused threads would leak the traceId otherwise        }    }    private String currentUser() {        ServletRequestAttributes attrs =                (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();        if (attrs == null) {            return "system";   // no request context in async or scheduled tasks        }        HttpServletRequest req = attrs.getRequest();        Object user = req.getSession().getAttribute("LOGIN_USER");        return user == null ? "anonymous" : user.toString();    }}

Notes

@annotation(opLog) binds the method's @OpLog instance to the OpLog opLog parameter — the pointcut directly means "only intercept methods carrying this annotation"
pjp.getArgs() gives the inputs, the value returned by proceed() is the output, and the timestamp difference is the duration — all in one pass
MDC stamps a traceId, so every log of one call carries it; a single grep reconstructs the whole trace
MDC.clear() in finally is not optional: web containers reuse threads, and without cleanup the previous request's traceId leaks into the next

Key point: never log sensitive fields such as passwords or ID numbers verbatim. Arrays.toString(pjp.getArgs()) dumps every argument indiscriminately; in production, mask by field allow-list before logging.

19 / 111

Section

3. Aspect two: permission checks with @RequirePerm

20 / 111

Requirement: before invoking a method, check whether the current user has permission; throw a business exception if not. For "block when the condition fails", @Before is enough — it cannot see the return value, but it does not need to.

21 / 111

java

package com.example.anno;import java.lang.annotation.*;@Target({ElementType.METHOD, ElementType.TYPE})@Retention(RetentionPolicy.RUNTIME)@Documentedpublic @interface RequirePerm {    String value();   // required permission code, e.g. "user:delete"}

22 / 111

java

package com.example.aspect;import com.example.anno.RequirePerm;import com.example.exception.ForbiddenException;import org.aspectj.lang.JoinPoint;import org.aspectj.lang.annotation.*;import org.springframework.stereotype.Component;import java.util.Set;@Aspect@Componentpublic class PermAspect {    // Assume permissions come from the login context; a static method here for brevity    @Before("@annotation(requirePerm)")    public void check(JoinPoint jp, RequirePerm requirePerm) {        Set<String> owned = CurrentUser.permissions();        if (!owned.contains(requirePerm.value())) {            throw new ForbiddenException("missing permission: " + requirePerm.value());        }    }}

23 / 111

Code

Codejava

package com.example.exception;public class ForbiddenException extends RuntimeException {    public ForbiddenException(String message) {        super(message);    }}

Notes

@Before runs before any business logic; throwing stops the call at the door and the target never executes
@Target allows both methods and classes: on a class it means "every method needs this permission", though @annotation only sees method-level ones — use @within for classes
Throwing a custom ForbiddenException rather than a bare RuntimeException lets the global handler distinguish a 403 from a 500

Note: the permission aspect should sit inside the logging aspect and outside the transaction aspect. If it is outermost, rejected requests still get a "success" log; if it is inside the transaction, a failure happens only after a transaction has opened, wasting a connection.

24 / 111

Section

4. Aspect three: rate limiting with @RateLimit

25 / 111

Requirement: limit how often an endpoint may be called. Below is a simple counter using ConcurrentHashMap and a time window, to show the idea:

26 / 111

java

package com.example.anno;import java.lang.annotation.*;@Target(ElementType.METHOD)@Retention(RetentionPolicy.RUNTIME)@Documentedpublic @interface RateLimit {    int limit() default 10;      // allowed calls per window    int seconds() default 1;     // window length in seconds}

27 / 111

Code

Codejava

package com.example.aspect;import com.example.anno.RateLimit;import com.example.exception.TooManyRequestsException;import org.aspectj.lang.annotation.*;import org.springframework.stereotype.Component;import java.util.Map;import java.util.concurrent.ConcurrentHashMap;@Aspect@Componentpublic class RateLimitAspect {    // key = method signature + caller, value = counter and window start    private final Map<String, Window> windows = new ConcurrentHashMap<>();    @Around("@annotation(rateLimit)")    public Object limit(ProceedingJoinPoint pjp, RateLimit rateLimit) throws Throwable {        String key = pjp.getSignature().toShortString() + "|" + CurrentUser.id();        long now = System.currentTimeMillis();        long span = rateLimit.seconds() * 1000L;        Window w = windows.compute(key, (k, old) -> {            if (old == null || now - old.start >= span) {                return new Window(now, 1);   // new window, count starts at 1            }            old.count++;            return old;        });        if (w.count > rateLimit.limit()) {            throw new TooManyRequestsException("too many requests, try later");        }        return pjp.proceed();    }    private static final class Window {        final long start;        int count;        Window(long start, int count) {            this.start = start;            this.count = count;        }    }}

Notes

compute is atomic, folding "is this a new window + increment" into one step and avoiding races under concurrency
Each method + user combination owns one Window, and the counter resets once the window expires
Going over the limit throws, letting the global handler return 429

28 / 111

Counting is easier to click through than to read about. These six frames walk one rejected call — pay attention to frame ②, where deciding "new window?" and incrementing are the same atomic operation; split them into two statements and you hand concurrency a race:

29 / 111

Animation

30 / 111

limit is the only numeric knob this aspect has, and it is meaningless without seconds. Drag it from 0 to 200 and see what each band actually buys you:

31 / 111

Tuner

TunerHow many calls per window still counts as "not rate limited"

@RateLimit.limit (with seconds)

10calls/windowNow 0 – 200

A per-user allowance for real business

Typical targets: order placement, verification codes, withdrawals — anything with side effects
The key carries the user id, so this limits one person, not one machine
Over the line throws TooManyRequestsException, mapped to 429 by the global handler
Pair this band with an alert: a spike in rejections usually means somebody is running an account pool

Downstream pressure25%

Collateral damage10%

Ask 'how fast may one person hit this endpoint' first, then derive limit and seconds — the numbers are the conclusion, not the starting point.

32 / 111

Trap

this in-memory limiter only works within a single instance, and windows grows without bound — keys are per "method + user", so memory grows with users. In production, switch to Redis + Lua: fixed windows with INCR plus EXPIRE, or a Lua script for a token bucket / sliding window. That shares one counter across instances and expires naturally. The aspect code can stay; only the storage changes to Redis.

33 / 111

Section

5. Aspect four: caching with @MyCache

34 / 111

Requirement: add caching to query methods, and understand what Spring Cache actually does. Hand-writing a @MyCache aspect makes key generation and the hit / miss flow immediately obvious:

35 / 111

java

package com.example.anno;import java.lang.annotation.*;@Target(ElementType.METHOD)@Retention(RetentionPolicy.RUNTIME)@Documentedpublic @interface MyCache {    String key();      // supports SpEL, e.g. "#id"    int ttl() default 60;   // expiry in seconds}

36 / 111

Code

Codejava

package com.example.aspect;import com.example.anno.MyCache;import org.aspectj.lang.ProceedingJoinPoint;import org.aspectj.lang.annotation.*;import org.aspectj.lang.reflect.MethodSignature;import org.springframework.core.DefaultParameterNameDiscoverer;import org.springframework.expression.*;import org.springframework.expression.spel.standard.SpelExpressionParser;import org.springframework.expression.spel.support.StandardEvaluationContext;import org.springframework.stereotype.Component;import java.util.Map;import java.util.concurrent.ConcurrentHashMap;@Aspect@Componentpublic class MyCacheAspect {    private final ExpressionParser parser = new SpelExpressionParser();    private final DefaultParameterNameDiscoverer names = new DefaultParameterNameDiscoverer();    private final Map<String, Entry> store = new ConcurrentHashMap<>();    @Around("@annotation(myCache)")    public Object cache(ProceedingJoinPoint pjp, MyCache myCache) throws Throwable {        MethodSignature sig = (MethodSignature) pjp.getSignature();        String key = sig.toShortString() + "#" + resolveKey(myCache.key(), sig, pjp.getArgs());        Entry hit = store.get(key);        long now = System.currentTimeMillis();        if (hit != null && now - hit.time < myCache.ttl() * 1000L) {            return hit.value;   // hit: return directly, the target never runs        }        Object value = pjp.proceed();   // miss: run the target method        store.put(key, new Entry(value, now));        return value;    }    private String resolveKey(String spEL, MethodSignature sig, Object[] args) {        StandardEvaluationContext ctx = new StandardEvaluationContext();        String[] params = names.getParameterNames(sig.getMethod());        for (int i = 0; params != null && i < params.length; i++) {            ctx.setVariable(params[i], args[i]);        }        return String.valueOf(parser.parseExpression(spEL).getValue(ctx));    }    private record Entry(Object value, long time) {}}

Notes

Key generation is the soul of caching: here "method signature + SpEL result" forms a unique key, so @MyCache(key = "#id") folds the id argument into it
A hit returns immediately and the target never executes; a miss calls proceed() and writes the result back
This mirrors Spring Cache: @Cacheable's key also supports SpEL, and underneath it is the same "look up → call on miss → store" flow

Tip: in real projects use Spring's @Cacheable with RedisCacheManager — do not build your own. The value of hand-writing this aspect is understanding "why a wrong cache key creates dirty data": drop an argument from the key and different inputs overwrite each other.

37 / 111

Those seven lines of resolveKey are exactly how @Cacheable(key = "#root.methodName + '#' + #id") works underneath: every parameter name is pushed into an evaluation context with setVariable, then SpEL computes the value. Switch to collection to see projection (#users.![id]) and selection (#users.?[status=='VIP']) evaluated, and switch to fail for the three classic miswrites — which are also the three errors you will hit in @Cacheable:

38 / 111

Kernel lab

TeaVMHow the #id in a cache key actually gets computedidle

literal separates #root from #this and #param, collection shows selection and projection, fail lines up three real error messages

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

39 / 111

Section

6. Ordering multiple aspects: @Order decides nesting

40 / 111

All four aspects may hit the same method. Who enters and leaves first is decided by @Order: smaller number is more outer. Here is a recommended order:

41 / 111

Table

Aspect	@Order	Position	Rationale
Audit log	1	Outermost	Must record whether it succeeds or fails
Rate limiting	2	Second	Reject early and save all downstream cost
Authorization	3	Middle	No need to open a transaction when rejecting
Transaction	—	Innermost (near target)	Wraps only the real business logic

42 / 111

Animation

43 / 111

Code

Codejava

@Aspect@Order(1)@Componentpublic class OpLogAspect { /* outermost: logging */ }@Aspect@Order(2)@Componentpublic class RateLimitAspect { /* second: rate limiting */ }@Aspect@Order(3)@Componentpublic class PermAspect { /* middle: authorization */ }

Notes

Entry order: log → rate limit → authorize → transaction → target
Return order is the reverse: target → transaction → authorize → rate limit → log
The core principle: the earlier an aspect can reject and the more resources it saves, the further out it should sit

44 / 111

Section

7. The aspect-vs-transaction risk: swallowing exceptions in around advice

45 / 111

This is the classic way an aspect breaks transactions.

46 / 111

java

// WRONG: @Around swallows the exception in try/catch@Around("@annotation(opLog)")public Object wrong(ProceedingJoinPoint pjp, OpLog opLog) throws Throwable {    try {        return pjp.proceed();    } catch (Exception e) {        log.error("call failed", e);        return null;          // exception eaten; the transaction advisor never sees it    }}

47 / 111

Code

Codejava

// RIGHT: log it, then rethrow so the transaction can roll back@Around("@annotation(opLog)")public Object right(ProceedingJoinPoint pjp, OpLog opLog) throws Throwable {    try {        return pjp.proceed();    } catch (Throwable e) {        log.error("call failed", e);        throw e;              // key: keep propagating so the boundary sees the failure    }}

Notes

In the "wrong" version the exception is caught and null is returned; the outer transaction advisor sees a normal return and does not roll back
The "right" version rethrows unchanged so the transaction advisor can roll back
In one line: around advice should "record and forward", not "digest exceptions". If you truly must swallow, you own the consistency consequences

Trap: catch (Exception e) inside @Around misses Error and parts of Throwable. Since around advice sits on the chain, either catch wide enough or simply let exceptions pass while only logging.

48 / 111

The whole hazard reduces to one question: is the layer that swallows sitting inside the transaction boundary? This picture puts both placements side by side — the left one writes dirty rows, the right one breaks nothing:

49 / 111

Diagram

Figure · A swallowing aspect inside versus outside the transaction

50 / 111

To make it stick, walk one throwing call layer by layer. Below is the stepping bench with the transaction's state refreshed on the right; press next and watch line ⑥ — that return null is where the dirty row is born:

51 / 111

Stepper

StepperHow a swallowed exception talks a transaction out of rolling back1 / 7

Step from 1 to 8 and watch the transaction state after line 6: it is still ACTIVE because it never received the exception

Code under debug

1orderService.createWithLog(dto); // (1) the call hits the proxy, entering the tx first

2[tx @Order(0)] tx.begin(); // (2) the transaction sits outermost — a wider boundary

3[audit @Order(100)] try { // (3) the logging aspect sits nearest the target

4 Object r = pjp.proceed(); // (4) one layer deeper is the target itself

5 [target] orderRepository.save(order); // (5) throws DataIntegrityViolationException here

6} catch (Exception e) { log.error("failed", e); return null; } // (6) the exception is eaten on this line

7// control returns to the tx interceptor: proceed() came back normally with a null

8[tx @Order(0)] tx.commit(); // (7) it saw no failure, so it commits

9return null; // (8) the caller believes it succeeded

Variables now

orderService	OrderServiceImpl$$SpringCGLIB$$0
aspects	tx (outer) + audit (inner)

Call stack

1OrderController.create

2proxy.createWithLog

1Two preconditions first: the call really went through the proxy (otherwise neither aspect runs), and this layout is 'transaction outside, logging inside'. The recommended table in Section 6 puts logging outermost — the final step says what that variant breaks.

52 / 111

Section

8. Trap: guard against nulls from RequestContextHolder

53 / 111

Trap

to grab the current request, the common call is RequestContextHolder.getRequestAttributes(). But it returns null in async threads, scheduled jobs, MQ consumers and unit tests — the request context lives in a ThreadLocal, so a thread switch loses it. Casting and calling getRequest() blindly throws a NullPointerException on the spot. Every aspect that reads the request from the context must null-check first: if unavailable, degrade (log as system) instead of crashing. Likewise, SecurityContextHolder cannot see the login state in async threads and needs a wrapper such as DelegatingSecurityContextRunnable to propagate it.

54 / 111

Section

9. Try it: the advice chain and the self-invocation trap

55 / 111

The demo below first shows the normal advice chain, then switches to "self-invocation", where you can see directly that once a method is called internally within the same class, every advice vanishes — the call never passes through the proxy:

56 / 111

Kernel lab

TeaVMVerify the advice chain and the self-invocation trapidle

Watch the normal chain first, then switch to self-invocation to see every advice vanish

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

57 / 111

The stepping bench in Section 7 was about where the exception goes; this one is its control experiment. Under error, check whether @AfterThrowing lets the exception continue upward and whether an @Around catch truncates it. Afterwards, reread that throw e line in Section 7 and you will see it is discipline, not style:

58 / 111

Kernel lab

TeaVMOn the error path, who catches itidle

Compare @AfterThrowing with a hand-written @Around catch: one records and keeps propagating, the other severs the chain

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

59 / 111

Section

10. Decision: rate limiting at the gateway or in an aspect

60 / 111

Decision

Decisionyou need to rate-limit a set of high-traffic endpoints. The team narrowed it to two options — at the gateway (Spring Cloud Gateway) or in-app with a `@RateLimit` aspect. How do you choose?

61 / 111

Section

11. Hands on: run the ordering and weaving of three aspects

62 / 111

The four demos here map onto this article's four threads: order (aoporder), where to intercept (pointcut), what weaving changes (weave), and how that log line actually lands (logchain).

63 / 111

The first is the animated version of Section 6's @Order table. Try all four branches: "@Order applies" builds the intuition that smaller means outer, "Nested timeline" lists the whole chain step by step, "Reversed order" shows why omitting @Order hands your ordering to chance, and "@Transactional versus custom aspect" explains a real incident — the message was already sent while the data was still uncommitted:

64 / 111

Kernel lab

TeaVMWho is really outside: nested aspect orderidle

Walk all four branches; memorise the full chain in step eleven

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

65 / 111

The second settles "which pointcut belongs to which aspect". Audit logging uses @annotation(opLog) down to the method, authorization can use @within across a whole class, timing uses execution( com.example.service...*(..)) over the entire package — three very different footprints, comparable branch by branch:

66 / 111

Kernel lab

TeaVMThree aspects, three pointcuts: how far each reachesidle

Then switch to execution parts to see which slots make the package-wide expression work

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

67 / 111

The third answers "what do I gain and what do I pay for an aspect". Under "No aspect" you get one stack frame with the body stirred into logging, try/catch and timing; under "Aspect woven" the same call carries three cross-cutting layers while business code stays untouched; and "Inside the chain" shows how proceed() passes control down and hands it back up:

68 / 111

Kernel lab

TeaVMBefore and after weaving, plus inside the chainidle

Do not miss steps six and seven of the chain branch — that symptom is exactly what Tier two of Section 15 makes you reproduce

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

69 / 111

The fourth covers the link beginners forget: how the line your logging aspect prints becomes a line in a file, and how the traceId gets attached. "Pattern layout" shows where %X{traceId} sits; "Level filtering" explains why dropping INFO to WARN in production makes audit lines vanish instantly:

70 / 111

Kernel lab

TeaVMDownstream of a logging aspect: where did my line goidle

Focus on the pattern and level branches — they explain 'I added logging but see nothing' in Tier two

Scenario

Click “Run demo” to execute the AOT-compiled Java kernel right in your browser, step by step.

71 / 111

Animation

72 / 111

Four demos done, and only one thing is left: when a requirement arrives, which of the four recipes do you copy? Left column is a real request (or a real incident), right column is the idiom that answers it:

73 / 111

Match

MatchRequirement ↔ the idiom that fitsMatched 0/6 · Missed 0

All six come from the scenarios in Sections 2-5; a wrong pair explains why that idiom cannot carry this job

Pick a card on the left first

74 / 111

From here you can type the commands yourself. This console is attached to the same container running in your browser and every response is computed by the kernel — boot, then beans to see who got a shell, then one line per thread of this article:

75 / 111

Console

76 / 111

Section

12. Sandbox: how should the three aspects be ordered?

77 / 111

Pick an ordering plan on the left; the right immediately gives "entry sequence / exit sequence / what goes wrong". With the very same aspects, merely changing numbers produces incidents like "the refused request also got a success log" or "rows were locked for nothing" — everything works, the semantics are wrong:

78 / 111

Sandbox

Sandbox@Order sandbox: log / rate limit / authz / transaction

Ordering plan

Call scenario

Result

enter LOG(1) -> RATE(2) -> AUTHZ(3) -> TX -> target
exit TX -> AUTHZ -> RATE -> LOG
[LOG] op=placeOrder args=[42] result=Order(id=42) took=86ms user=zhang

The recommended layout: logging outermost, so its duration is the full user-visible time including limiting, authz and commit.

79 / 111

Note

the no-order cell deserves emphasis. Omitting @Order does not mean "outermost by default" or "first by default"; the aspect takes Ordered.LOWEST_PRECEDENCE, literally Integer.MAX_VALUE. When several aspects share that value, Spring can only order them by collection sequence — derived from component-scan traversal, @Configuration declaration order and auto-configuration sorting, all of which can shift across environments and builds. The only fix is an explicit number on every aspect, spaced generously (10, 20, 30) so a future aspect can slot in without renumbering.

80 / 111

Section

13. Common errors quick reference

81 / 111

Every fragment below pastes straight into a search box; this table collects the failures only practical aspects produce:

82 / 111

Table

Error text (fragment)	Real cause	30-second rescue	Read deeper in
HTTP 200 with `data` null, no new row in the database, no message downstream, and not one exception anywhere	`@Around` forgot to call `pjp.proceed()`: the chain broke at that layer, so the target never ran once	Put a breakpoint at the first line of the around advice and confirm `proceed()` fires; fix the shape: the body must contain `return pjp.proceed();`, with everything else wrapped around it in `try/finally`	#13 @AspectJ details Section 8 · this article, Section 11 weave chain branch
`BeanCurrentlyInCreationException: Error creating bean with name 'permAspect': Requested bean is currently in creation: Is there an unresolvable circular reference?`	The aspect `@Autowired`s some Service, while that Service is itself a target of this aspect, so "aspect → service → proxy decision for the service" forms a cycle	Prefer pushing the query into a small collaborator that is never advised; if you truly need the Service, put `@Lazy` on the field (better: `ObjectProvider<T>`) so delivery happens only when first used	#10 Circular dependency · #14 AOP internals, station one
Log order drifts between machines or restarts (forgetting `@Order` yields random order)	Aspects without `@Order` and not implementing `Ordered` all take `Ordered.LOWEST_PRECEDENCE`, degrading relative order to advisor collection order	Give every aspect an explicit `@Order(n)` with wide gaps (10, 20, 30); assert the log sequence in an integration test, not a unit test	This article, Section 12 `no-order` · #13 Section 6
The transaction "does not work": data was written, an exception was thrown, yet nothing rolled back	An `@Around` sitting outside the transaction ate the exception in `catch` (`return null`), so the boundary observed a normal return	Around advice only "records and forwards": `catch (Throwable e) { log.error(...); throw e; }`; if you genuinely must swallow, you own the consistency	Section 7 · #31 Transaction internals
`NullPointerException` right after `(ServletRequestAttributes) RequestContextHolder.getRequestAttributes()` inside an aspect	Async threads, scheduled jobs, MQ consumers and unit tests have no request context, so the call returns `null`; the context lives in a `ThreadLocal` and a thread switch loses it	Null-check before use and degrade to `system` when absent; propagate the login state across threads with a wrapper such as `DelegatingSecurityContextRunnable`	Section 8 · #40 Async & scheduling
`java.lang.ClassCastException: class com.sun.proxy.$Proxy42 cannot be cast to class com.example.service.UserServiceImpl`	The aspect casts `pjp.getTarget()` to the implementation class while the container handed out a JDK proxy	Call through the interface; or set `spring.aop.proxy-target-class=true` (already the Boot default); to read fields use `AopUtils.getTargetClass()` instead	#14 AOP internals Section 5 · #12 Dynamic proxy
`IllegalArgumentException: error at anonymous pointcut expression around this`	A broken pointcut string: the variable in `@annotation(opLog)` differs from the parameter name, brackets unbalanced, or the annotation given as a simple name	Check brackets and fully qualified names segment by segment; paste the parameter name verbatim	#13 @AspectJ details Section 13
The caching aspect still executes the method after a hit (or conversely returns stale data when it should refresh)	Key generation dropped an argument so different inputs overwrite each other; or the TTL check sits after `proceed()`	The key must include "method signature + every argument affecting the result"; the hit branch must `return` before any side effect	Section 5 · #32 Redis & caching
Passwords or ID numbers end up verbatim in the audit log	`Arrays.toString(pjp.getArgs())` dumps every argument indiscriminately	Serialize by an allow-list of fields or mask specific ones; keep `@OpLog(recordArgs = false)` as the escape hatch	Section 2 key point

83 / 111

Trap

writing catch (Exception e) inside @Around misses Error and other Throwables; but "to be safe" catching wide and then return null walks into rows one and four above at once. There are only two safe shapes: either do not catch at all and close out in finally, or catch Throwable and always throw e.

84 / 111

Tier two's fix for self-invocation — "inject your own proxy" — produces a very direct stack if you forget the switch. The message literally contains the remedy; the trick is recognising it. Practise:

85 / 111

Triage

Error triageIllegalStateException: Cannot find current proxy

Calling AopContext.currentProxy() without exposeProxy

To stop an aspect from being skipped on a self-call you rewrote this.createTwice() as ((OrderService) AopContext.currentProxy()).createTwice(). It compiles, and blows up on the first production call.

java.lang.IllegalStateException: Cannot find current proxy: Set 'exposeProxy' property on Advised to 'true' to make it available, and ensure that AopContext.currentProxy() is invoked in the same thread as the AOP invocation containing the self-reference

at org.springframework.aop.framework.AopContext.currentProxy(AopContext.java:95)

at com.example.order.service.OrderService.createTwice(OrderService.java:61)

at com.example.order.service.OrderService$$SpringCGLIB$$0.createTwice(<generated>)

at com.example.order.controller.OrderController.submit(OrderController.java:28)

at java.base/java.lang.Thread.run(Thread.java:840)

Click the frame you blame — guessing is allowed

No pressure: guess the exception first, then which line actually made the call.

86 / 111

Section

14. Quick quizzes

87 / 111

Quiz

Check yourselfYour `PermAspect` @Autowired-injects `UserService` to look up permissions, and that `UserService` is itself matched by the same aspect. Startup fails with `BeanCurrentlyInCreationException`. What is the most reasonable fix?

Pick one — you get feedback right away

88 / 111

Quiz

Check yourselfThree aspects carry no @Order at all. Which statement about their execution order is correct?

Pick one — you get feedback right away

89 / 111

Section

15. Exercises

90 / 111

Section

Tier one · Follow along

91 / 111

Goal: build a timing aspect you could ship as-is, walking through "annotation → pointcut binding → tiered logging → aggregation", and see how it nests with the audit-logging aspect. Drop this into a Spring Boot project (needs spring-boot-starter-aop).

92 / 111

java

package com.example.anno;import java.lang.annotation.*;@Target(ElementType.METHOD)@Retention(RetentionPolicy.RUNTIME)   // mandatory, otherwise the aspect cannot read it reflectively@Documentedpublic @interface Cost {    /** business action name for logs and aggregates; defaults to the method name */    String value() default "";    long warnMs() default 200;    long errorMs() default 1000;}

93 / 111

java

package com.example.aspect;import com.example.anno.Cost;import org.aspectj.lang.ProceedingJoinPoint;import org.aspectj.lang.annotation.Around;import org.aspectj.lang.annotation.Aspect;import org.slf4j.Logger;import org.slf4j.LoggerFactory;import org.springframework.core.annotation.Order;import org.springframework.stereotype.Component;import java.util.Map;import java.util.concurrent.ConcurrentHashMap;import java.util.concurrent.atomic.LongAdder;@Aspect@Component@Order(2)                    // with OpLogAspect at @Order(1) these form the onion's two skinspublic class CostAspect {    private static final Logger log = LoggerFactory.getLogger(CostAspect.class);    private final Map<String, LongAdder> calls = new ConcurrentHashMap<>();    private final Map<String, LongAdder> totalMs = new ConcurrentHashMap<>();    @Around("@annotation(cost)")        // the name cost must equal the parameter name below    public Object around(ProceedingJoinPoint pjp, Cost cost) throws Throwable {        String action = cost.value().isEmpty() ? pjp.getSignature().getName() : cost.value();        long start = System.nanoTime();        calls.computeIfAbsent(action, k -> new LongAdder()).increment();        try {            return pjp.proceed();       // mandatory: without it the target never runs once        } finally {            long ms = (System.nanoTime() - start) / 1_000_000;            totalMs.computeIfAbsent(action, k -> new LongAdder()).add(ms);            String line = "[COST] {} took={}ms thresholds(warn={}, error={})";            if (ms >= cost.errorMs()) {                log.error(line, action, ms, cost.warnMs(), cost.errorMs());            } else if (ms >= cost.warnMs()) {                log.warn(line, action, ms, cost.warnMs(), cost.errorMs());            } else {                log.info(line, action, ms, cost.warnMs(), cost.errorMs());            }        }    }    /** handy for exercises and debugging: print the aggregates */    public String summary() {        StringBuilder sb = new StringBuilder("[SUMMARY] ");        calls.forEach((k, v) -> sb.append(k).append("=").append(v.sum())                .append(" calls/").append(totalMs.get(k).sum()).append("ms "));        return sb.toString();    }}

94 / 111

java

package com.example.service;import com.example.anno.Cost;import org.springframework.stereotype.Service;@Servicepublic class OrderService {    @Cost("placeOrder")    public Long create(String sku) throws InterruptedException {        Thread.sleep(50);                 // normal case: INFO        return 42L;    }    @Cost(value = "reconcile", warnMs = 20)    public String reconcile() throws InterruptedException {        Thread.sleep(300);                // past warnMs: WARN        return "done";    }    @Cost(value = "report", errorMs = 100)    public String report() throws InterruptedException {        Thread.sleep(150);                // past errorMs: ERROR        return "big-report";    }}

95 / 111

java

// start the app and call the three methods in turn@SpringBootApplicationpublic class CostDemoApplication {    public static void main(String[] args) throws Exception {        try (ConfigurableApplicationContext ctx =                     SpringApplication.run(CostDemoApplication.class, args)) {            OrderService svc = ctx.getBean(OrderService.class);            svc.create("A-1");            svc.reconcile();            svc.report();            System.out.println(ctx.getBean(com.example.aspect.CostAspect.class).summary());        }    }}

96 / 111

Expected log output (timestamps and prefixes elided):

97 / 111

Code

Codetext

[COST] placeOrder took=51ms thresholds(warn=200, error=1000)[COST] reconcile took=301ms thresholds(warn=20, error=1000)[COST] report took=151ms thresholds(warn=200, error=100)[SUMMARY] placeOrder=1 calls/51ms reconcile=1 calls/301ms report=1 calls/151ms

Notes

The three lines are INFO / WARN / ERROR respectively, obvious at a glance from console colouring
About @Order(2): mark Section 2's OpLogAspect as @Order(1) on the same method and the sequence must be [AROUND-IN(OpLog)] → … [COST] … → [AROUND-OUT(OpLog)] — the two skins of the onion
The variable in @annotation(cost) equals the parameter Cost cost exactly. Rename the parameter to Cost c and binding fails loudly; that is the other half of quiz one in Section 14

98 / 111

Section

Tier two · Variations

99 / 111

Delete @Order(2) from CostAspect and leave OpLogAspect with only @Component. You will observe: across three restarts the entry and exit order may change, and whenever logging lands inside the timing aspect the [COST] figure reads lower than what users actually waited for — the live version of the no-order cell in Section 12.
Replace return pjp.proceed(); with return 999L;. You will observe: the Thread.sleep inside OrderService#create stops happening (elapsed drops to 0ms), the result becomes 999, and no exception is raised anywhere. Feel now why a caching aspect returning early on purpose is correct.
Add @Transactional to create, make report() throw IllegalStateException, and set CostAspect to @Order(-1) (outside the transaction). You will observe: [COST] now includes commit and rollback time. Then change the finally into catch (Exception e) { log...; return null; } and dirty data lands in the database — because the exception never reached the transaction boundary. That is the iron rule of this section.
Set logging.level.com.example.aspect=warn in properties. You will observe: the INFO line disappears entirely, leaving only WARN and ERROR. Go back to the logchain demo in Section 11, branch "level filtering", and you will see the advice still ran; the gate simply kept the line out.

100 / 111

Section

Tier three · Build one

101 / 111

Combine this article's three aspects into a minimal shippable audit kit: @OpLog (audit log) + @Cost (timing) + @RequirePerm (authorization), without them fighting each other.

102 / 111

Give all three explicit @Order values: log 10, authorization 20, timing 30 (wide gaps so future aspects can slot in)
One traceId: only the outermost logging aspect writes it into MDC; the other two read only, and the outermost removes it in finally with MDC.remove("traceId") (never clear() — that wipes other people's keys)
The authorization aspect must not depend on anything it advises: extract the permission lookup behind a PermissionReader interface with an implementation the pointcut never matches
Expose counters somewhere cheap (a small endpoint or a startup line): hits and rejections per aspect
Mask sensitive fields: besides @OpLog(recordArgs = false), add String[] maskFields() printing *** for named fields

103 / 111

Acceptance checklist: ① one successful call emits three lines sharing one traceId, in onion order; ② one unauthorized call causes zero database writes yet leaves an "attempted escalation by whom" audit record; ③ removing any single aspect's @Component leaves the other two's behaviour and logs identical, proving no coupling; ④ write an integration test asserting those three log lines' sequence, and confirm deleting one @Order makes it fail — only then can a regression be caught by CI.

104 / 111

Section

16. Self-check

105 / 111

Self-check

without looking, explain why "annotation + aspect" separates intent from implementation, and why @Retention(RUNTIME) is a hard requirement here.

106 / 111

Self-check

when three aspects hit one method, what ordering do you recommend and why, one sentence each?

107 / 111

Self-check

there are exactly two correct ways to handle exceptions in @Around. Name them, and explain why the third (catch then return null) also breaks the transaction.

108 / 111

Self-check

what risk does @Autowired-ing a Service into an aspect create, and what are the two fixes?

109 / 111

Self-check

why must the result of RequestContextHolder be null-checked, and in which threads is it guaranteed to be null?

110 / 111

Mantra: **to change behaviour use Around, merely to observe use the other four; whoever can reject sooner sits further out; Around must call proceed, and exceptions must be rethrown unchanged.**

111 / 111

Summary

this section gives four reusable aspects — audit logging with @Around (who, args, result, duration, traceId via MDC), authorization with @Before (throw a business exception when unauthorized), rate limiting with @Around (ConcurrentHashMap + time window; move to Redis + Lua in production) and caching with @Around (SpEL key, return immediately on a hit). Order multiple aspects with @Order, where a smaller number is more outer; the recommended order is "log > rate limit > authorize > transaction". Two iron rules to finish: around advice must rethrow after logging, or the transaction will not roll back; and reading the request from RequestContextHolder must be null-checked, because in async and scheduled tasks it is always null.