cli: also log applier debug messages to debug log file

[3u13r]

Context

Currenlty, when the coordinator is not reachable, the last log line is

{"time":"2024-10-18T11:59:38.778068783+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":38},"msg":"Running init RPC"}

<nothing else here, next line only if init is successful>

{"time":"2024-10-18T12:01:08.364242086+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":77},"msg":"Initialization request successful"}

Proposed change(s)

• Use existing debugLogger, that logs both to a file and to stderr, in the applier that makes the init call to the coordinator.

Now the logs also containt he following messages each time the CLI tries to init (those were previously only available directly in the cli output but not in the constellation-debug.log file)

{"time":"2024-10-24T11:57:16.602504601+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/cli/internal/cmd.(*applyCmd).runInit","file":"cli/internal/cmd/applyinit.go","line":38},"msg":"Running init RPC"}
{"time":"2024-10-24T11:57:16.602531232+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMasterSecret","file":"internal/constellation/apply.go","line":125},"msg":"Generating master secret"}
{"time":"2024-10-24T11:57:16.602556592+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMasterSecret","file":"internal/constellation/apply.go","line":138},"msg":"Generated master secret key and salt values"}
{"time":"2024-10-24T11:57:16.602652653+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMeasurementSalt","file":"internal/constellation/apply.go","line":144},"msg":"Generating measurement salt"}
{"time":"2024-10-24T11:57:16.602675503+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).GenerateMeasurementSalt","file":"internal/constellation/apply.go","line":149},"msg":"Generated measurement salt"}
{"time":"2024-10-24T11:57:16.602700083+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).Init","file":"internal/constellation/applyinit.go","line":93},"msg":"Initialization call","endpoint":"34.117.169.242:9000"}
{"time":"2024-10-24T11:57:16.602804065+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*initDoer).Do","file":"internal/constellation/applyinit.go","line":191},"msg":"Created protoClient"}
{"time":"2024-10-24T11:57:16.602855575+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":34},"msg":"Connection state started as \"IDLE\""}
{"time":"2024-10-24T11:57:16.602976596+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"IDLE\""}
{"time":"2024-10-24T11:57:16.619469197+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"CONNECTING\""}
{"time":"2024-10-24T11:57:16.619528677+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":42},"msg":"Connection state ended with \"TRANSIENT_FAILURE\""}
{"time":"2024-10-24T11:57:16.619659429+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*Applier).Init.func1","file":"internal/constellation/applyinit.go","line":88},"msg":"Encountered error (retriable: true): \"init call: rpc error: code = Unavailable desc = connection error: desc = \\\"transport: authentication handshake failed: EOF\\\"\""}
{"time":"2024-10-24T11:57:46.606037431+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/constellation.(*initDoer).Do","file":"internal/constellation/applyinit.go","line":191},"msg":"Created protoClient"}
{"time":"2024-10-24T11:57:46.606093582+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":34},"msg":"Connection state started as \"IDLE\""}
{"time":"2024-10-24T11:57:46.606321074+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"IDLE\""}
{"time":"2024-10-24T11:57:46.623866876+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":36},"msg":"Connection state changed to \"CONNECTING\""}
{"time":"2024-10-24T11:57:46.623954387+02:00","level":"DEBUG","source":{"function":"github.com/edgelesssys/constellation/v2/internal/grpc/grpclog.LogStateChangesUntilReady.func1","file":"internal/grpc/grpclog/grpclog.go","line":42},"msg":"Connection state ended with \"TRANSIENT_FAILURE\""}

Checklist

• Add labels (e.g., for changelog category)
• Link to Milestone

[netlify]

✅ Deploy Preview for constellation-docs canceled.

Name	Link
🔨 Latest commit	a7b2a2c
🔍 Latest deploy log	https://app.netlify.com/sites/constellation-docs/deploys/671a32e751804400080c5d3f

[thomasten]

I don't understand why we have two loggers in this func. Should we just log everything with this logger?

[3u13r]

The other logger log is now only used in the warnLogger, which in turn is only used https://github.com/edgelesssys/constellation/blob/euler/cli/extend-file-debug-log/cli/internal/cmd/applyinit.go#L33. I think in general terms, we want to print warning non-structured, so not with slog.

The simplest solution would be to use the debugLogger instead of log when creating the warnLogger and in the warnLogger's implementation we debug log additionally when calling Warn.
EDIT: this would print the warning twice to the user, once structured and once unstructured when debug is enabled, which is fine in my opinion.

[3u13r]

The current state (last commit) is a proposal for this version.

[thomasten]

I agree that printing the warning as structured debug log again is fine.

[github-actions]

Coverage report

Package	Old	New	Trend
cli/internal/cmd	57.90%	57.90%	↔️

[thomasten]

LGTM