Logging of multiple parameters safely

[chris05atm]

What happened?

I have a 3-parameter tuple that is used as a composite data store key. I end up writing code that looks like this:

log.error("bad thing happened on {} {} {}",
UnsafeArg.of("key", primaryKey),
UnsafeArg.of("branch", branch),
SafeArg.of("semanticVersion", SafeLog.of(semanticVersion)));

This 3-parameter tuple of [key, branch, semanticVersion] is common across logging statements and safe exceptions because my application needs all 3 parameters to make sense of what is going on.

The construction of logging and exceptions with these three parameters over and over again is tedious and error prone.

I attempted to wrap this logic with something like this:

@SuppressWarnings("rawtypes")
    public static Arg[] argsFromPersistedObjectKeyArgs(PersistedObjectKey key) {
        Arg[] args = new Arg[3];
        args[0] = UnsafeArg.of(KEY_LOG_PARAM, key.key());
        args[1] = SafeArg.of(BRANCH_LOG_PARAM, key.branch());
        args[2] = SafeArg.of(SEMANTIC_VERSION_LOG_PARAM, key.semanticVersion());
        return args;
    }

and use it like so:

log.warn("table found no key for ({})", (Object[]) SafeLoggerUtils.argsFromPersistedObjectKeyArgs(key));

but:

1. I have to use an (Object[]) prefix to avoid ambiguous method calls
2. I end up throwing Baseline Error Prone Checks for the usage cast to (Object[])

warning: [Slf4jLogsafeArgs] slf4j log statement does not use logsafe parameters for arguments [1]
(see https://github.com/palantir/gradle-baseline#baseline-error-prone-checks)

To remove the error prone check I have to annotate my methods with Slf4jLogsafeArgs suppressed warnings.

What did you want to happen?

I would like the logging and exception methods to handle non-Args-only objects constructed with an interface that supports both safe and unsafe logging. This may already exist but no one has been able to point me to it so far.

[gm2211]

Update: as an interim solution I've implemented this for one of our codebases:

/**
 * A class to simplify grouping together log args while preserving the ability to add more args when logging.
 * Can be used as an alternative for MDC.
 *
 * Example:
 *
 * var commonLogArgs = ArgList.of(
 *   SafeArg.of("service", rid.service()),
 *   UnsafeArg.of("locator", rid.locator()));
 *
 * log.info(
 *   "Some message",
 *   commonLogArgs
 *     .append(UnsafeArg.of("ip-address", ipAddress))
 *     .asObjectArray());
 *
 * or if log: SafeLogger
 *
 * log.info(
 *   "Some message",
 *   commonLogArgs
 *     .append(UnsafeArg.of("ip-address", ipAddress))
 *     .asList());
 *
 * or
 *
 * new SafeRuntimeException("message", commonLogArgs.asArray());.
 */
public final class ArgList {
    private final Set<Arg<?>> args = new LinkedHashSet<>(); // preserves insertion order

    public static ArgList of(Arg<?>... args) {
        ArgList argList = new ArgList();
        Collections.addAll(argList.args, args);
        return argList;
    }

    private ArgList() {}

    /** Adds a new arg to the end of this arg list. */
    public ArgList append(Arg<?> arg) {
        args.add(arg);
        return this;
    }

    /** This can be used as follows: log.info("some message", argList.asObjectArray());. */
    public Object[] asObjectArray() {
        return StreamEx.of(args).toArray(Object[]::new);
    }

    /** This can be used as follows: throw new SafeRuntimeException("some message", argList.asArray());. */
    public Arg<?>[] asArray() {
        return StreamEx.of(args).toArray(Arg[]::new);
    }

    /** This can be used as follows (if log: SafeLogger): log.info("some message", argList.asList());. */
    public List<Arg<?>> asList() {
        return List.copyOf(args);
    }
}

---

I found myself in a similar situation where you might want to take an unsafe string, parse it and log it as a set of sub-components that are either safe or unsafe.

A clear example to complement the one already listed above is ResourceIdentifier - you might find yourself having something like:

public final class Args {
  private Args() { }
  
  @SuppresWarnings("unchecked")
  public static Arg<String>[] rid(String ridString) {
    try {
       var rid = ResourceIdentifier.valueOf(ridString);
       return new Arg[] {
         SafeArg.of("service", rid.service()), 
         SafeArg.of("instance", rid.instance()), 
         SafeArg.of("type", rid.type()),
         UnsafeArg.of("unredacted-locator", rid.locator()),
         SafeArg.of("locator", redactedOrSafe(rid.locator()))
      };
    } catch (RuntimeException e) {
       return new Arg[] { UnsafeArg.of("rid-with-invalid-format", ridString) };
    }
}

This runs into the same problem described in this issue:

log.info("Something happened to resource", (Object[]) Args.rid(ridString));

which gets even worse if you want to log extra arguments

// This will not work
log.info("Something happened to resource", (Object[]) Args.rid(ridString), SafeArg.of("foo", "bar"));

// You have to do something a little janky like
Arg[] args = StreamEx.of(Args.rid(ridString))
   .append(SafeArg.of("foo", "bar"))
   .toArray(Arg[]::new);
log.info("Something happened to resource", (Object[]) args);

---

Proposal:

We introduce a new type:

class CompositeArg extends Arg<Object> {
    List<Arg<?>> subArgs;
}

and then modify SafeLogger to "explode" CompositeArgs whenever it finds them.

This way you could do something like:

public final class Args {
  ....
  public static final CompositeArg rid(String ridString) {
     ...
     return CompositeArg.of(
       SafeArg.of("service", rid.service(), 
       ...., 
       UnsafeArg.of("unredacted-locator", rid.locator())
     );
     ...
  }
}

// And then..
log.info("Something happened to resource", Args.rid(ridString), SafeArg.of("foo", "bar"));

[Regan-Koopmans]

Is this something that would still be valuable to work on?