Background

Record the project with facets so that all methods, classes, and constructors marked with @Log comments have information written to the log file.

Question

The method appears to be called recursively by a layer of depth, but the code does not show any such recursive relationships.

Actually

Recorded results:

2018-09-25 12:17:29,155 |↷|   EmailNotificationServiceBean#createPayload([SECURE])
2018-09-25 12:17:29,155 |↷|     EmailNotificationServiceBean#createPayload([{service.notification.smtp.authentication.password=password, mail.smtp.port=25, service.notification.smtp.authentication.username=dev@localhost, mail.mime.allowutf8=true, mail.smtp.auth=false, mail.smtp.starttls.enable=false, mail.smtp.timeout=10000, mail.smtp.host=localhost}])
2018-09-25 12:17:29,193 |↷|       EmailPayloadImpl#<init>([{service.notification.smtp.authentication.password=password, mail.smtp.port=25, service.notification.smtp.authentication.username= dev@localhost, mail.mime.allowutf8=true, mail.smtp.auth=false, mail.smtp.starttls.enable=false, mail.smtp.timeout=10000, mail.smtp.host=localhost}])
2018-09-25 12:17:29,193 |↷|         EmailPayloadImpl#validate([SECURE])
2018-09-25 12:17:29,194 |↷|           EmailPayloadImpl#validate([{service.notification.smtp.authentication.password=password, mail.smtp.port=25, service.notification.smtp.authentication.username= dev@localhost, mail.mime.allowutf8=true, mail.smtp.auth=false, mail.smtp.starttls.enable=false, mail.smtp.timeout=10000, mail.smtp.host=localhost}, SMTP connection and credentials])
2018-09-25 12:17:29,195 |↷|         EmailPayloadImpl#setMailServerSettings([SECURE])
2018-09-25 12:17:29,196 |↷|           EmailPayloadImpl#setMailServerSettings([{service.notification.smtp.authentication.password=password, mail.smtp.port=25, service.notification.smtp.authentication.username=dev@localhost, mail.mime.allowutf8=true, mail.smtp.auth=false, mail.smtp.starttls.enable=false, mail.smtp.timeout=10000, mail.smtp.host=localhost}])

Expected

Expected logging results:

2018-09-25 12:17:29,155 |↷|   EmailNotificationServiceBean#createPayload([SECURE])
2018-09-25 12:17:29,193 |↷|     EmailPayloadImpl#<init>([SECURE])
2018-09-25 12:17:29,193 |↷|       EmailPayloadImpl#validate([SECURE])
2018-09-25 12:17:29,195 |↷|       EmailPayloadImpl#setMailServerSettings([SECURE])

Code

Log:

@Aspect
public class LogAspect {
    @Pointcut("execution(public @Log( secure = true ) *.new(..))")
    public void loggedSecureConstructor() { }

@Pointcut("execution(@Log( secure = true ) * *.*(..))")
    public void loggedSecureMethod() { }

@Pointcut("execution(public @Log( secure = false ) *.new(..))")
    public void loggedConstructor() { }

@Pointcut("execution(@Log( secure = false ) * *.*(..))")
    public void loggedMethod() { }

@Pointcut("execution(* (@Log *) .*(..))")
    public void loggedClass() { }

@Around("loggedSecureMethod() || loggedSecureConstructor()")
    public Object logSecure(final ProceedingJoinPoint joinPoint) throws Throwable {
        return log(joinPoint, true);
    }

@Around("loggedMethod() || loggedConstructor() || loggedClass()")
    public Object log(final ProceedingJoinPoint joinPoint) throws Throwable {
        return log(joinPoint, false);
    }

private Object log(final ProceedingJoinPoint joinPoint, boolean secure) throws Throwable {
        final Signature signature = joinPoint.getSignature();
        final Logger log = getLogger(signature);

final String className = getSimpleClassName(signature);
        final String memberName = signature.getName();
        final Object[] args = joinPoint.getArgs();
        final CharSequence indent = getIndentation();
        final String params = secure ? "[SECURE]" : Arrays.deepToString(args);

log.trace("\u21B7| {}{}#{}({})", indent, className, memberName, params);

try {
            increaseIndent();

return joinPoint.proceed(args);
        } catch (final Throwable t) {
            final SourceLocation source = joinPoint.getSourceLocation();
            log.warn("\u2717| {}[EXCEPTION {}] {}", indent, source, t.getMessage());
            throw t;
        } finally {
            decreaseIndent();
            log.trace("\u21B6| {}{}#{}", indent, className, memberName);
        }
    }

Log interface definition:

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE, ElementType.CONSTRUCTOR})
public @interface Log {
    boolean secure() default false;
}

Decompiled service bean:

@Log
public class EmailNotificationServiceBean
implements EmailNotificationService {

@Log(secure = true)
    @Override
    public EmailPayload createPayload(Map<String, Object> settings) throws NotificationServiceException {
        Map<String, Object> map = settings;
        JoinPoint joinPoint = Factory.makeJP((JoinPoint.StaticPart)ajc$tjp_2, (Object)this, (Object)this, map);
        Object[] arrobject = new Object[]{this, map, joinPoint};
        return (EmailPayload)LogAspect.aspectOf().logSecure(new EmailNotificationServiceBean$AjcClosure7(arrobject).linkClosureAndJoinPoint(69648));
    }

Load implementation:

@Log
public class EmailPayloadImpl extends AbstractPayload implements EmailPayload {

@Log(secure = true)
    public EmailPayloadImpl(final Map<String, Object> settings)
                    throws NotificationServiceException {
        validate(settings, "SMTP connection and credentials");
        setMailServerSettings(settings);
    }

@Log(secure = true)
    private void validate(final Map<String, Object> map, final String message)
                    throws NotificationServiceException {
        if (map == null || map.isEmpty()) {
            throwException(message);
        }
    }

@Log(secure = true)
    private void setMailServerSettings(final Map<String, Object> settings) {
        this.mailServerSettings = settings;
    }

Question

What causes this:

• Secure = true constructor annotation attribute to ignore; and
• Do you want to call and log the validate and setMailServerSettings methods twice (once safe, once unsafe)?

I suspect these issues are related.

Solution:

To fix the duplication problem, you need to adjust the loggedClass() entry point definition:

@Pointcut("execution(* (@Log *) .*(..)) && !@annotation(Log)")
public void loggedClass() { }

Also find a link to a proof of concept in the Additional Information section.

Description:

Issues related to connection points (defined by @Pointcut annotations), whose patterns intersect each other – this is why duplicates in the logs.

In our case, all @Pointcut are named descriptive enough, for example:

• loggedClass() covers all methods in a class annotated by @Log.
• loggedSecureMethod() covers all methods annotated by @Log(secure = true). Others are similar to this one, so let’s ignore them to explain.

So, if EmailPayloadImpl uses @Log annotations and EmailPayloadImpl.validate() uses @Log(secure = true) – we will have 2 activity connection points: one secure and a non-secure. This will result in 2 log entries being added.

Suppose we want to introduce precedence in annotations, i.e. method-level annotations should override class-level annotations – the easiest way is to avoid cross-connection point patterns.

So we need 3 sets of methods:

Method
1. with @Log(secure = true) annotation = loggedSecureMethod().

Method

2. with @Log annotation = loggedMethod().

3. There are no annotations @Log, but in a class there is a method that @Log annotations, i.e., :

   @Pointcut("execution(* (@Log *) .*(..)) && !@annotation(Log)")
   public void loggedClass() { }
   

Additional information:

1. If you also need to handle @Log at the class level (secure = true) – you need to add additional connection points similar to loggedClass(), of course.
2. Added on GitHub