feat: custom log output

[osterman]

what

• provide a way to emit a nice little custom message with interpolation for each step

use-case

logformat = "%Y-%M-%d %H:%m:%s [${job}] ${message}"
job "terraform init" {
  log = "initializing project in ${var.moduledir}"
  ...
}

example output

./mycli terraform init --verbose
2020-04-07 22:00:00 [terraform init] initializing eks project in /tmp/foobar
2020-04-07 22:00:00 [terraform plan] planning eks project

[mumoshu]

@osterman Hey! Thanks.

I'm interested in this idea, but could you elaborate a bit more on your expectations?

The nature of HCL is that we can't detect the order among different kinds of blocks. So we can't process run and log in the order of occurrence. runs are processed in the order of occurrences and log are processed in the order of their occurrences, but we do this:

run "foo" {
}

log = "after foo"

run "bar" {
}

log = "after bar"

So perhaps I would make log block exclusive to run or exec. I mean, you can only use one of log, run and exec within a job. Does it look ok to you?

[osterman]

Hrmm... the way I was thinking about it is variant2 when executing a job would look for the presence of a log message. If it shows it, it would always emit that first. If it's not present it would do nothing. So the order is fixed at "first", not relative to the position in the block. To me it seems like it would work like options or parameters that you presumably process before processing the exec which depends on the values. In this case, you'd process log after processing options and parameters, but before processing exec or run

[mumoshu]

@osterman Thanks! That makes sense. I'm not sure if log is the correct term though.

It's already used by the log block and we can't use the same symbol(log) for HCL attribute and HCL block at the same time. Also log doesn't say whether it's run before/after the exec/job/step/etc.

Do you have any other alternative that sounds better in terms of the above concerns?

After a quick brain storming I came up with:

• prelog
• prelude
• print, echo, info (but this doesn't solve the issue about the timing of the text being printed

A different approach would be somehow enhancing the existing log block so that you can print a message only before any cmd/job is exec'ed/ran.

[osterman]

How about this... we extend the current log { ... } ?

logformat = "%Y-%M-%d %H:%m:%s [${job}] ${message}"

job "test" {
  run "echo" {
    message = "foo"
  }

  log {
    prelude = "initializing project in ${var.moduledir}"
    epilogue = "initialized project in ${var.moduledir}"
    # collect is optional
    collect {
      condition = event.type == "exec"
      format = "exec=${jsonencode(event.exec)}"
    }
}

Or...

logformat = "%Y-%M-%d %H:%m:%s [${job}] ${message}"

job "test" {
  run "echo" {
    message = "foo"
  }

  # debug is the log level, could have info, warn, etc...
  log "debug" {
    message = "initializing project in ${var.moduledir}"
    sequence = 0
   }

   log "collect" {
      condition = event.type == "exec"
      format = "exec=${jsonencode(event.exec)}"
    }
}

Or...

logformat = "%Y-%M-%d %H:%m:%s [${job}] ${message}"

job "test" {
  run "echo" {
    message = "foo"
  }

  # debug is the log level, could have info, warn, etc...
  prelude "debug" {
    message = "initializing project in ${var.moduledir}"
   }

  ...
}

Then maybe with a --log-level option we can only display debug events.

[mumoshu]

Thanks! The concept of the log level seems necessary and useful.
HOwever, I'm not yet sure how the whole API around log collection and this log emission can be designed concise and easy to use.
Please give me a few days to think about this :)