UX: improve log formatting & info (on refresh & show)

[DavidGOrtega]

Log what we store in logs and events within the terraform status using the terraform CLI during refresh using logrus. This way would be easier to visualise the logs within the Terraform CLI.

This also applies to current existing logs in creation and destroy.

According to @dmpetrov feedback ideally:

• Instance lifecycle
  • Creation with info about price
  • Termination
• Data syncing
• Script
  • Setup environment
  • Script logs
  • Status
    • Started/Terminated
    • Success/Failed

[0x2b3bfa0]

Log what we store in logs and events within the terraform status using the terraform CLI during refresh using logrus. This way would be easier to visualise the logs within the Terraform CLI.

Sounds interesting. Can you please add a bit more of context?

• Why and how should we use a logging library like logrus?
  • Terraform providers can't print to the command–line tool standard output/error at will; see hashicorp/terraform-plugin-sdk#145 and Allow resources to report more detailed progress from CRUD hashicorp/terraform#17267 for more information.¹
  • Logs can be sent through hooks (#393) instead, but it might be as (in)convenient for the end user as running terraform show or saving logs locally by other means.
  • There is no point in using hooks to integrate with log aggregation services (e.g. AWS CloudWatch) from the client side and requiring users to run terraform refresh periodically. If we ever choose to integrate at this level, log collection should be performed in the cloud machines; probably through the official agents.
• Should we try to alter the behavior of terraform refresh to display additional information?

It looks like we're starting to find out that Terraform wasn't meant as a command–line application prototyping toolkit, but rather as a specialized tool to manage persistent (i.e. non ephemeral) infrastructure.

Footnotes

1. Users can set the TF_LOG environment variable to collect provider logs in real time, but relying on this behavior is unrealistic from the user experience standpoint. ↩

[DavidGOrtega]

Logs can be sent through hooks (#393) instead

Exactly we could control a bit where or how to see the logs aside the infamous TF_LOG like syslog out-of-the-box

from the client side and requiring users to run terraform refresh periodically

In reality this task is much more looking at the future. At some point we should have all the logic control within go. WE need to create that code in go that handles the task and do the data syncing in go... a proper executor engine and no the current solution that allow us to have more control on this and other things. But at least I can see the logs on refresh without having to read uncomfortable json in the command line

Should we try to alter the behavior of terraform refresh to display additional information

Not that much than the having logs if the setup TF_LOG or thanks to logrus we can control a bit the logs.

[DavidGOrtega]

It looks like we're starting to find out that Terraform wasn't meant as a command–line application prototyping toolkit, but rather as a specialized tool to manage persistent (i.e. non ephemeral) infrastructure.

We are not using and never did use Terraform because is a command–line application prototyping toolkit.
I always liked it because of HCL. At DVC we have implemented a JSON extension to support something that would be similar in HCL.
Loops, vars, etc...

[0x2b3bfa0]

But at least I can see the logs on refresh without having to read uncomfortable json in the command line

Do you mean that the sole fact of running terraform refresh would print logs to the standard output? 🤔 It wuld be clearer if you added some examples.

[0x2b3bfa0]

But at least I can see the logs on refresh without having to read uncomfortable json in the command line

Do you mean that the sole fact of running terraform refresh would print logs to the standard output? 🤔 It would be clearer if you added some examples.

[DavidGOrtega]

Do you mean that the sole fact of running terraform refresh would print logs to the standard output? 🤔 It would be clearer if you added some examples.

With export TF_LOG im able to see the logs using logrus we could also output to something more friendly, and when we have the executor in place we could see real time logs where ever we wanted

[DavidGOrtega]

At least the MVP is:
I refresh and I can see whats going on easier than having to grep or cat a json file, even if I have to enable TF_LOG. Additionally we could use syslog via logrus and only that opens an entire world of centralised logging

[DavidGOrtega]

The last sentence is more from a UX perspective. In any case the task is discern an implement how we can bring the information that the users are demanding. Regarding to the events and task information. Even if at the last we are going to use pure JSON.

[0x2b3bfa0]

With export TF_LOG im able to see the logs using logrus

Of course, but we can't ask users to manually set TF_LOG to use our provider. 🙃 Also, enabling that logging mode will also add noise from Terraform debug messages.

we could also output to something more friendly

For example? A file?

and when we have the executor in place we could see real time logs where ever we wanted

How?

[0x2b3bfa0]

I refresh and I can see whats going on easier than having to grep or cat a json file

Do you mean that terraform refresh would output logs directly like this?

resource "iterative_task" "example" {
  script    = <<-END
    #!/bin/sh
    echo "Hello world from the cloud!"
  END
}

$ terraform refresh
iterative_task.example: Refreshing state... [id=tpi-example-a1b2c3-d4e5f6]
[INFO] Hello world from the cloud!

even if I have to enable TF_LOG.

Again, this is a line we shouldn't probably cross. Asking users to enable this feature during the normal operation of the program is rather cumbersome and inelegant.

[0x2b3bfa0]

Additionally we could use syslog via logrus and only that opens an entire world of centralised logging

Centralised logging from the client side sounds like the worst of both worlds. 🤔 Still, “centralised logging” in general sounds like an interesting topic to explore after the public release.

[0x2b3bfa0]

The last sentence is more from a UX perspective.

Which sentence?

_In any case the task [1] is discern an implement how we can bring the information that the users are demanding. Regarding to the events and task [2] information.

If “the task [1]” means “this issue” and “task [2]” means task, I enthusiastically agree.

Even if at the last we are going to use pure JSON.

Like in #389 (comment)? 🤔 Doesn't sound especially user friendly.

[DavidGOrtega]

For example? A file?

Syslog i.e. being able to redirect syslog to many decentralised logging solutions.

Again, this is a line we shouldn't probably cross.

Ehrr... why not? If we just only have this way to enable logs... at least we have somehow and they are able to see it properly

If “the task [1]” means “this issue” and “task [2]” means task, I enthusiastically agree.

correct

[0x2b3bfa0]

Ehrr... why not? If we just only have this way to enable logs... at least we have somehow and they are able to see it properly

Terraform explicitly forbids providers from interacting with the terminal standard input/output/error for good reasons. It's an infrastructure management tool, not a command–line interface toolkit.

• Allow resources to report more detailed progress from CRUD hashicorp/terraform#17267 (comment)
• Ability for Terraform plugins to give status updates via stdout in CLI hashicorp/terraform-plugin-sdk#145

Asking users to set TF_LOG=INFO before using our provider would be a controversial design choice for the following reasons:

1. Noise: this debug mode doesn't just print the logs we want, but every log from Terraform Core and every provider; running TF_LOG=INFO terraform refresh already prints ~40 extra lines by default, with no resources.
2. Order: plan/apply tasks run in parallel and log lines aren't guaranteed to be printed contiguously, and output may contain interleaved logs from different providers and resources.
3. Format: providers don't have any control over the log line prefix, which adds 30+ characters with a worthless local timestamp to every line.
4. Convenience: requiring users to enable this mode as part of the default experience is just chaotic evil.

[0x2b3bfa0]

Syslog i.e. being able to redirect syslog to many decentralised logging solutions.

It's still unclear to me what's the use for syslog in this scenario: legacy syslog was replaced by systemd-journald long ago. Modern distributions don't even support syslog network logging out of the box. systemd/systemd#15200.

• Having our provider write cloud machine task logs locally to the system where it runs is similarly chaotic. Logs in the journal are interleaved with other system logs, thus hard to parse; and providers aren't expected to have this kind of side effect anyway.

• Having our provider write cloud machine task logs to a remote service — if that's what you propose — doesn't seem especially useful, because it would require users to run terraform refresh periodically.

• Having cloud machines write task logs to appropriate cloud services periodically, instead/apart of writing them to object storage — current approach — could be a nice addition, but doesn't seem to solve any of our immediate issues.

[DavidGOrtega]

Having our provider write cloud machine task logs locally to the system where it runs is similarly chaotic. Logs in the journal are interleaved with other system logs, thus hard to parse; and providers aren't expected to have this kind of side effect anyway.

When I read this I have the impression that you never had to deal with logs. Tools like logstash, graylog, are used and then you are able to filter, search... Rsyslog is the standard here

[DavidGOrtega]

Asking users to set TF_LOG=INFO before using our provider would be a controversial design choice for the following reasons

The whole team agreed on using TF_LOG in the last meeting

[0x2b3bfa0]

When I read this I have the impression that you never had to deal with logs.

https://en.wikipedia.org/wiki/Ad_hominem

Tools like logstash, graylog, are used and then you are able to filter, search...

None of those tools is intended for local use. Again, does your proposal include a centralized log aggregation service?

Rsyslog is the standard here

Yes, but, again, not locally. Also, not every log aggregation service supports it natively; e.g. AWS CloudWatch. XKCD 927

The whole team agreed on using TF_LOG in the last meeting

Except from this Slack message:

Terraform discards provider debug logs by default. Users can set the TF_LOG_PROVIDER and TF_LOG_PATH environment variables to route these logs to a file or to the terraform standard output. Still, those debug logs are not meant for end users: resource blocks are processed in parallel, and log lines from different operations are interleaved in unpredictable ways.