Logging and troubleshooting

[machaval]

Logging

Current log function allows the user to print any value in a very simple way. The log function uses the wiretap pattern. It is the identity function fun log<T>(valueToLog: T): T that has a side effect that prints the valueToLog in the standard output or the logging mechanism in the case of running in mule. With this a user can take any expression or sub expression wrap it into a log function and still work. For example

var a = payload.user.name

If for some reason we don't understand why name is not being retrieved we can go and modify

var a = log(payload.user).name

and it will not affect any execution or result.

This function has been used to troubleshoot any script, and looks like it was widely adopted. The problem with this function is that it is more a println than a log meaning that it lacks a basic feature of logging such as level o a way to configure when to log and when not based on some configuration. So this means that there shouldn't be any log call in any normal flow execution in production. And this is a big problem because there is no way to troubleshoot production scripts without modifying the scripts.

Proposal

The proposal is to cover this gaps by adding two features.

1. Adding the log level to the log function
2. Support a way to configure the logging

Adding the log level to the log function

The proposed log levels are

1. Debug
2. Info
3. Warning
4. Error

And the way we can do this is by adding a third parameter to the log function with default value Info and we will not break compatibility

This is the existing signature of the log function

fun log <T>(prefix: String = "", value: T): T

The proposed function will be

type LogLevel = "Debug" | "Info" | "Warning" | "Error"
fun log <T>(prefix: String = "", value: T, level: LogLevel = "Info"): T

And I proposed adding new dedicated functions that log at the different levels

type LogLevel = "Debug" | "Info" | "Warning" | "Error"
fun log <T>(prefix: String = "", value: T, level: LogLevel = "Info"): T


fun logDebug <T>(prefix: String = "", value: T): T = log(prefix, value, "Debug")

fun logInfo <T>(prefix: String = "", value: T): T = log(prefix, value, "Info")

fun logWarning <T>(prefix: String = "", value: T): T = log(prefix, value, "Warning")

fun logError <T>(prefix: String = "", value: T): T = log(prefix, value, "Error")

Support a way to configure the logging

Now that we can have log levels we should be able to turn logs on and off without needing to change the code. For this we need a configuration file that applies at the runtime level.

The idea is to allow to set the level for different kind of scopes

Scopes:

• Runtime applies to all the log calls executed by a given engine
• Module applies to all the log calls in a given Module
• Function applies to all the log calls in a given Function

The proposed configuration file is a dataweave file called logs-config.dwl where a user can configure log level for different scopes for example

[
  {
    scope: "Runtime",
    level: "Warning"
  },
  {
    scope: "Module",
    module: "acme::MyModule"
    level: "Info"
  },
  {
    scope: "Function",
    module: "acme::MyModule"
    function: "test"
    level: "Debug"
  },

]

So for this configuration what it expresses is that any log call that is not inside of acme::MyModule only Warnings or Errors are going to be executed. And inside acme::MyModule is "Info" unless the log is inside a function named test that is "Debug"

This way we can have a hierarchical scoping that allows the user to control when to log and when not.

[machaval]

Here is an old issue with a similar ask #47

[rhoegg]

What about a curry function that produces a configured logger function? With overloads, I think we could achieve both these goals, while keeping the invocations simple with just a prefix and a pass through return value.

type LogLevel = "Debug" | "Info" | "Warning" | "Error"
type Logger<T> = (prefix: String = "", value: T, level: LogLevel = "Info") -> T

fun logger(level: LogLevel): Logger<T> = (prefix: String = "", value: T) -> // log at specified level

this way, invoking it might look like this:

logger("Info")(payload.user).name

I like the configuration data model, and I think we could provide a curry function that accepts aLoggingConfiguration as an alternative to loading it from the classpath.

Developers could have the flexibility to reuse logging configurations through using variables:

var myLoggerConfig = dw::util::Logging::loggerConfig([
  {
    scope: "Runtime",
    level: "Warning"
  },
  {
    scope: "Module",
    module: "acme::MyModule"
    level: "Info"
  },
  {
    scope: "Function",
    module: "acme::MyModule"
    function: "test"
    level: "Debug"
  }
])

---
myLoggerConfig("Info")(payload.user).name

[machaval]

I love the idea of also being able to configure it programatically... my only concern about this is that you need to change your code unless you use like a readUrl kind of thing to obtain it from some file

[iglosiggio]

Another useful thing to have would be a way to group logs into tasks (similar to Apples Activity Tracing API). These can be disabled by default (making all calls to these APIs no-ops) but allow detailed information when requested.

Some utopic examples 😛.

We can add a new native:

type TaskDescription = {
  name: String
  /* This is an open object, allowing extra information to be snuggled here */
}
fun describesWorkFor<T>(description: String | TaskDescription, v: T): T = ???

This is the identity function but:

1. Forces evaluation of v
2. The context of that evaluation includes the description of the task being done

The expected usage allows for both unstructured tasks:

fun doAuthentication(creds: Credentials): AuthToken | AuthError =
  "Authenticating ${creds.username}" describesWorkFor do {
    /* Imagine some complex code that does authentication
       and may perform additional logging happens here
       (or is called from here) */
    var authResponse = ???
    ---
    if (authResponse.success) authResponse.token
    else (authResponse as ErrorResponse).error
  }

And structured ones:

fun doAuthentication(creds: Credentials): AuthToken | AuthError =
  {
    name: "Authentication",
    username: creds.username
  } describesWorkFor do {
    /* Imagine some complex code that does authentication
       and may perform additional logging happens here
       (or is called from here) */
    var authResponse = ???
    ---
    if (authResponse.success) authResponse.token
    else (authResponse as ErrorResponse).error
  }

Information-wise it should be enough to just log <"enter", TaskDescription> and <"exit"> events. Having this facility allows to use something like the trace_event format of Catapults trace-viewer, enabling users to time-slice their logs at easily (and maybe even investigate performance issues).

[machaval]

This solution propose a more structural solution where we can encapsulate code blocks. This is very similar to the interceptors concept that we already have in DW where one can Annotate a function and delegate an interceptor to another function. Now that we can annotate any expression we can potencially take the same apporach to any expression and we can produce the same thing using annotations and interceptors that will allow us the same thing that you are saying no?
BTW Thanks for this!