[Bug]: Duplicate console log lines in the Docker image, and startup logging must explain failures #409

Summary

Two related logging problems:

1. Every log line is written twice to the console in the Docker image.
2. The startup log doesn't always explain what's wrong. An operator should be able to tell from the log alone why the server doesn't start or doesn't work, without enabling debug logging or reading stack traces.

1. Duplicate console output (bug)

Observed in the Docker image (production configuration):

[14:33:56 INF] Backtier-SslMode: VerifyFull
[14:33:56 INF] Backtier-SslMode: VerifyFull
[14:33:57 INF] The connection to the data store at comet-db:5432 is encrypted using TLSv1.3 TLS_AES_256_GCM_SHA384 (Backtier:SslMode VerifyFull)
[14:33:57 INF] The connection to the data store at comet-db:5432 is encrypted using TLSv1.3 TLS_AES_256_GCM_SHA384 (Backtier:SslMode VerifyFull)

Cause: the console output is configured twice.

• CometServer/Program.cs:74 adds it in code: .ReadFrom.Configuration(...).WriteTo.Console().
• Since Change default log writing to console instead of Loki. #401 ("Change default log writing to console instead of Loki"), appsettings.Production.json also has "WriteTo": [ { "Name": "Console" } ].

appsettings.Development.json uses GrafanaLoki in WriteTo, so the duplicates only appear with the production configuration, which is the one in the Docker image (the Dockerfile renames it to appsettings.json).

Fix: remove .WriteTo.Console() from Program.cs and let configuration decide the outputs. Add { "Name": "Console" } to appsettings.Development.json so local runs keep console output. This also lets operators turn console logging off or change its format through configuration or environment variables.

Related finding: appsettings.Production.json writes the log file to logs/log-development-.txt. That should be logs/log-.txt or logs/log-production-.txt.

2. Logging must explain what's wrong in each scenario

While working on #406 the startup was tested against real PostgreSQL servers in a range of failure scenarios. The table shows what the log says after the #406 changes (branch feature/GH406-postgresql-tls), and what's still missing.

Proposed work

• Fix the duplicate console output (section 1) and the production log file name.
• Stop at once on permanent database errors that aren't TLS related: 28P01 invalid password, 28000 rejected by pg_hba.conf, 3D000 database doesn't exist, 42501 insufficient privilege. Each with an explanation that names the setting to check (Backtier:UserName, Backtier:Password, Backtier:Database, server pg_hba.conf). This extends the DataStoreConnectionStatus / DescribeTlsConfigurationError mechanism introduced for [Feature]: Configurable TLS and certificate verification for the PostgreSQL connection #406.
• Program.cs logs CDP4-COMET REST API Ready to accept connections at ... before the data store has been checked and the migrations have run, so the log claims the server is ready while it may stop a few seconds later. Log the listening address as "listening on", and log "ready" only once CometStartUpService has finished (CometHasStartedService.SetHasStartedAndIsReady(true)).
• Log the .NET runtime version at startup (see [Update]: Docker base image aspnet:10.0.7 is six security releases behind (latest 10.0.13) #408).
• Review the remaining startup and authentication-plugin log messages against these rules:
  • one line per problem at Warning/Error/Critical, stating what failed, why, and which setting to change
  • stack traces only at Debug
  • no secrets (passwords, tokens, connection strings)
• WRN No XML encryptor configured. Key {...} may be persisted to storage in unencrypted form. appears at every container start. Decide whether the data-protection keys need to be persisted and protected (for example a volume plus a certificate), or document why the warning can be ignored.
• Add the scenario table above to the wiki as a troubleshooting page: log message → cause → fix.

Acceptance criteria

• Each log line appears once in the console of the Docker image. Development still logs to the console.
• Every scenario in the table has a one-line Critical/Warning message that names the cause and the setting to change, with no stack trace at Information level or above.
• Permanent database errors (wrong password, unknown user or database, pg_hba.conf rejection) stop startup at once instead of waiting for BacktierWaitTime.
• "Ready" is only logged once the server is actually ready.
• Troubleshooting page in the wiki.

Related

• [Feature]: Configurable TLS and certificate verification for the PostgreSQL connection #406: TLS for the PostgreSQL connection (introduces the TLS diagnostics and the stop-at-once behaviour for TLS errors).
• [Update]: Docker base image aspnet:10.0.7 is six security releases behind (latest 10.0.13) #408: Docker base image update (log the runtime version).
• Change default log writing to console instead of Loki. #401: introduced the console output in the production configuration.
• [Add] grafana-loki logging sink #288: Grafana Loki sink (closed).