feat: rewrite output #260

nvloff-f3 · 2024-06-25T02:31:57Z

Description

This is a complete rewrite of the f1 UI and text output across the package. With the goal to natively support structured logging using the Go standard library log/slog package.

New Features

Support JSON Logging with LOG_FORMAT=json
Support log levels with LOG_LEVEL
Automatically output structured logs when f1 is run from non-interactive shells. No longer showing term escapes in log aggregators when running in a container.
Automatically output structured logs when --verbose option is enabled so that human readable and structured logs are no longer interwoven in the same output.
Use log/slog as logging back-end with a logrus backwards compatibility layer. The logrus logger exposed has a custom handler defined that translates log entries to slog.

Deprecation

Deprecate: --verbose-fail option. It no longer has an effect. Typical f1 use case is running unattended. Prefer clearly defined logging behavior to conditional based on scenario success.
Deprecate: t.Logger() that returns a logrus.Logger it will be removed in future versions.

Changes

Default log output to stdout instead of stderr
Add a 4 character random component to log file names to avoid duplicate files created in the same second ( from f1-scenario-YYYY-MM-DD_HH-MM-SS.log to f1-scenario-XXXX-YYYY-MM-DD_HH-MM-SS.log)

Changes in behavior

No changes for interactive shells

When run from non-interactive shells - default to structured logs

When `verbose` is enabled, make sure the full output is structured log regardless of interactive mode.

A mix of structured and non-structured is difficult to manage for log collection systems.

internal/run/output.go

jcinnamond-form3

Some feedback to give you things to think about.

jcinnamond-form3 · 2024-07-03T08:21:28Z

internal/run/outputer.go

+var _ ui.Outputer = (*Output)(nil)
+
+func (o *Output) Display(outputable ui.Outputable) {
+	if o.printer.Interactive && o.logToFile {


If find logToFile confusing here. I would have expected logToFile to control whether or not Log is called, not whether or not a message is printed to (what looks like) stdout

jcinnamond-form3 · 2024-07-03T08:59:27Z

internal/ui/output.go

+type Outputer interface {
+	Display(outputable Outputable)
+	Logger() *slog.Logger
+	Printer() *Printer


Is this used anywhere? I might be missing something but I can't see anywhere that calls Printer() other than one place that initialises a new outputer, passing in the parent Printer()

jcinnamond-form3 · 2024-07-03T10:05:18Z

internal/ui/printer.go

+type Printer struct {
+	Writer      io.Writer
+	ErrWriter   io.Writer
+	Interactive bool


Interactive is only used by Outputer implementations, so maybe it belongs in there rather than in the Printer

jcinnamond-form3 · 2024-07-03T12:32:41Z

internal/run/outputer.go

+	"github.com/form3tech-oss/f1/v2/internal/ui"
+)
+
+type Output struct {


Do you need a new implementation of Output? Isn't this the same as ui.Output if you move logToFile into there and default it to true?

jcinnamond-form3 · 2024-07-03T12:37:28Z

internal/ui/output.go

+	return &ConsoleOutput{printer: printer}
+}
+
+func NewDiscardOutput() *Output {


I found this name confusing because it only discards logs, not interactive output. I think it should also discard the Printer output, or rename it to make its behaviour clearer.

jcinnamond-form3 · 2024-07-03T12:39:53Z

internal/ui/output.go

+	return NewOutput(logger, printer)
+}
+
+func NewOutput(logger *slog.Logger, printer *Printer) *Output {


A minor thing, but I'd move NewOutput closer to the declaration of the type and it's methods. At the moment the definition of ConsoleOnlyOutput and DiscardOutput in the middle make this less obvious when scanning the code.

jcinnamond-form3 · 2024-07-03T12:40:07Z

internal/ui/output.go

+	return o.printer
+}
+
+func NewConoleOnlyOutput() *ConsoleOutput {


Suggested change

func NewConoleOnlyOutput() *ConsoleOutput {

func NewConsoleOnlyOutput() *ConsoleOutput {

jcinnamond-form3 · 2024-07-03T13:59:26Z

internal/ui/output.go

+}
+
+func (o *ConsoleOutput) Logger() *slog.Logger {
+	return nil


This is unsafe because places using the logger aren't doing a nil check first. In practice you're only using the console only logger to list the scenarios so it doesn't also log, but in that case I'd suggest that this isn't really an Outputer. Why not just print to stdout from scenarios_cmd if that's all it's ever going to do?

jcinnamond-form3 · 2024-07-03T14:13:31Z

internal/ui/messages.go

In almost every case (except InteractiveMessage) these types just call through to the underlying printer or logger. This seems more complicated that is necessary. The whole interaction between Outputable, Outputer, and Printer seems wrong to me. The flow is roughly:

Create an Outputable (some kind of message)
Send it to an Outputer
The Outputer asks its Printer whether it should print and log, or just log
It then calls a method on the Outputable, passing in the Printer or Logger
The Outputable mostly does nothing other than call a corresponding method on the Printer or Logger (except some extra formatting for errors, or (unusually) some logic for interactive messages to not output anything)

I wonder if you can move most of this into the Outputer. It would have enough config to know where to send messages (without having to ask the Printer), and could provide an interface so that the caller could say Error, Info, ... InteractiveOnly, LogOnly. I've only half thought this through, but I'm not convinced you need this many levels of abstraction here.

This is a complete rewrite of the f1 UI and text output across the package. With the goal to natively support structured logging using the Go standard library log/slog package. New features: - Support JSON Logging with LOG_FORMAT=json - Support log levels with LOG_LEVEL - Automatically output structured logs when f1 is run from non-interactive shells. No longer showing term escapes in log aggregators when running in a container. - Automatically output structured logs when --verbose option is enabled so that human readable and structured logs are no longer interwoven in the same output. - Use log/slog as logging back-end with a logrus backwards compatibility layer. The logrus logger exposed has a custom handler defined that translates log entries to slog. Deprecation: - Deprecate: --verbose-fail option. It no longer has an effect. Typical f1 use case is running unattended. Prefer clearly defined logging behavior to conditional based on scenario success. - Deprecate: t.Logger() that returns a logrus.Logger it will be removed in future versions. Changes: - Default log output to stdout instead of stderr - Add a 4 character random component to log file names to avoid duplicate files created in the same second ( from f1-scenario-YYYY-MM-DD_HH-MM-SS.log to f1-scenario-XXXX-YYYY-MM-DD_HH-MM-SS.log) Changes in behavior: - No changes for interactive shells - When run from non-interactive shells - default to structured logs - When verbose is enabled, make sure the full output is structured log regardless of interactive mode. A mix of structured and non-structured is difficult to manage for log collection systems.

nvloff-f3 force-pushed the nvloff-logger-rework branch 4 times, most recently from ff0a3df to 36aea06 Compare June 25, 2024 05:45

github-advanced-security bot found potential problems Jun 25, 2024

View reviewed changes

internal/run/output.go Fixed Show fixed Hide fixed

nvloff-f3 force-pushed the nvloff-logger-rework branch 13 times, most recently from 4f035b8 to 26aa2fe Compare July 1, 2024 07:29

nvloff-f3 marked this pull request as ready for review July 2, 2024 02:16

nvloff-f3 requested a review from a team as a code owner July 2, 2024 02:16

miketonks-form3 previously approved these changes Jul 2, 2024

View reviewed changes

jcinnamond-form3 reviewed Jul 3, 2024

View reviewed changes

nvloff-f3 dismissed miketonks-form3’s stale review via 71dd9c1 July 5, 2024 02:07

nvloff-f3 force-pushed the nvloff-logger-rework branch from 71dd9c1 to 3869ffa Compare July 8, 2024 01:56

chore: review feedback

bfd6047

nvloff-f3 force-pushed the nvloff-logger-rework branch from 3869ffa to bfd6047 Compare July 8, 2024 02:08

chore(docs): link outputable with the views

52a9b81

mlornac approved these changes Jul 10, 2024

View reviewed changes

nvloff-f3 merged commit 4209fa2 into master Jul 10, 2024
4 checks passed

nvloff-f3 deleted the nvloff-logger-rework branch July 10, 2024 06:29

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: rewrite output #260

feat: rewrite output #260

nvloff-f3 commented Jun 25, 2024 •

edited

Loading

jcinnamond-form3 left a comment

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

jcinnamond-form3 Jul 3, 2024

	func NewConoleOnlyOutput() *ConsoleOutput {
	func NewConsoleOnlyOutput() *ConsoleOutput {

feat: rewrite output #260

feat: rewrite output #260

Conversation

nvloff-f3 commented Jun 25, 2024 • edited Loading

Description

New Features

Deprecation

Changes

Changes in behavior

No changes for interactive shells

When run from non-interactive shells - default to structured logs

When verbose is enabled, make sure the full output is structured log regardless of interactive mode.

jcinnamond-form3 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nvloff-f3 commented Jun 25, 2024 •

edited

Loading

When `verbose` is enabled, make sure the full output is structured log regardless of interactive mode.