Skip to content

fix: provisionerd: add more context to logs emitted, fix log level #6508

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Mar 8, 2023
Merged

fix: provisionerd: add more context to logs emitted, fix log level #6508

Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
7289b87
fix: provisionerd: add more context to logs emitted, fix log level
johnstcn Mar 8, 2023
d010b47
log provision fail at level ERROR
johnstcn Mar 8, 2023
ca2794d
Revert "log provision fail at level ERROR"
johnstcn Mar 8, 2023
eba54ad
handle all sdkproto.LogLevel enums
johnstcn Mar 8, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 21 additions & 2 deletions provisionerd/runner/runner.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -880,7 +880,7 @@ func (r *Runner) buildWorkspace(ctx context.Context, stage string, req *sdkproto
}
switch msgType := msg.Type.(type) {
case *sdkproto.Provision_Response_Log:
r.logger.Info(context.Background(), "workspace provision job logged",
r.logProvisionerJobLog(context.Background(), msgType.Log.Level, "workspace provisioner job logged",
slog.F("level", msgType.Log.Level),
slog.F("output", msgType.Log.Output),
slog.F("workspace_build_id", r.job.GetWorkspaceBuild().WorkspaceBuildId),
Expand All @@ -895,8 +895,9 @@ func (r *Runner) buildWorkspace(ctx context.Context, stage string, req *sdkproto
})
case *sdkproto.Provision_Response_Complete:
if msgType.Complete.Error != "" {
r.logger.Info(context.Background(), "provision failed; updating state",
r.logger.Warn(context.Background(), "provision failed; updating state",
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

note: logging at level ERROR breaks existing unit tests, and I don't want to set slogtest.IgnoreErrors.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Understandable. It might be the "correct" approach though, if we expect errors to be logged, then setting IgnoreErrors seems like the right course of action.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mafredri Would you agree that anything "ERROR" and above should be mainly for events useful to a system administrator?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could be relevant for e.g. template authors, but generally I doubt coder/provisioner logs (via logger) would be surfaced to anyone but systems admins.

slog.F("state_length", len(msgType.Complete.State)),
slog.F("error", msgType.Complete.Error),
)

return nil, &proto.FailedJob{
Expand Down Expand Up @@ -1120,3 +1121,21 @@ func redactVariableValues(variableValues []*sdkproto.VariableValue) []*sdkproto.
}
return redacted
}

// logProvisionerJobLog logs a message from the provisioner daemon at the appropriate level.
func (r *Runner) logProvisionerJobLog(ctx context.Context, logLevel sdkproto.LogLevel, msg string, fields ...slog.Field) {
switch logLevel {
case sdkproto.LogLevel_TRACE:
r.logger.Debug(ctx, msg, fields...) // There's no trace, so we'll just use debug.
case sdkproto.LogLevel_DEBUG:
r.logger.Debug(ctx, msg, fields...)
case sdkproto.LogLevel_INFO:
r.logger.Info(ctx, msg, fields...)
case sdkproto.LogLevel_WARN:
r.logger.Warn(ctx, msg, fields...)
case sdkproto.LogLevel_ERROR:
r.logger.Error(ctx, msg, fields...)
default: // should never happen, but we should not explode either.
r.logger.Info(ctx, msg, fields...)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In theory, it could be possible that a customer misconfigures the Coder deployment, INFO will be selected as default logging level, and it can blow up the cluster if there are thousands of logs, but that's just theory.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

INFO is the status quo, and the only way for someone to select a different level is to set CODER_VERBOSE or --verbose, both of which need to be set explicitly.

}
}