Shift to winston for logging

[daikema]

This pull request migrates from controller logging using console methods (and occasionally util functions verboseError or verboseLog), to controller logging using winston.

As part of this migration the verbose parameter has been replaced with the option to specify a logLevel, where any messages of or above that level will be logged. Rather than only logging to the console, with the changes log level and log format (text vs json) can be independently specified for both console and file.

Text log example (log level is colorized when run):

2025-05-20T15:00:12.593Z [INFO]: Started logging to /tmp/carta-json.log
2025-05-20T15:00:12.595Z [INFO]: Loaded config from /etc/carta/config.json
2025-05-20T15:00:13.903Z [INFO]: Using /etc/carta/userlookupOidc.txt for user mapping
2025-05-20T15:00:13.904Z [INFO]: Updated usermap with 3 entries
2025-05-20T15:00:14.534Z [INFO]: Serving packaged CARTA frontend (Version 5.0.0-beta.1c)
2025-05-20T15:00:14.576Z [INFO]: Setting up JWKS management for https://auth.server.name/realms/default/protocol/openid-connect/certs
2025-05-20T15:00:14.594Z [INFO]: Connected to test on localhost:27017 (Authenticated: No)
2025-05-20T15:00:14.595Z [INFO]: Server initialised successfully at https://server.name/
2025-05-20T15:00:14.596Z [INFO]: Started listening for login requests on port 8000

JSON log example:

{"level":"info","message":"Started logging to /tmp/carta-json.log","timestamp":"2025-05-20T15:00:12.595Z"}
{"level":"info","message":"Loaded config from /etc/carta/config.json","timestamp":"2025-05-20T15:00:12.595Z"}
{"level":"info","message":"Using /etc/carta/userlookupOidc.txt for user mapping","timestamp":"2025-05-20T15:00:13.904Z"}
{"level":"info","message":"Updated usermap with 3 entries","timestamp":"2025-05-20T15:00:13.904Z"}
{"level":"info","message":"Serving packaged CARTA frontend (Version 5.0.0-beta.1c)","timestamp":"2025-05-20T15:00:14.534Z"}
{"level":"info","message":"Setting up JWKS management for https://auth.server.name/realms/default/protocol/openid-connect/certs","timestamp":"2025-05-20T15:00:14.576Z"}
{"level":"info","message":"Connected to test on localhost:27017 (Authenticated: No)","timestamp":"2025-05-20T15:00:14.594Z"}
{"level":"info","message":"Server initialised successfully at https://server.name/","timestamp":"2025-05-20T15:00:14.595Z"}
{"level":"info","message":"Started listening for login requests on port 8000","timestamp":"2025-05-20T15:00:14.597Z"}

Still TBD

• Documentation updates outside the schema JSON + CLI --help (should be done before converting from a draft pull request)
• Creation of a corresponding pull request to the new schemas repo

Questions / Tentative answers

• Should I keep the console logging colorized even if writing to something like a file? (less gets confused by the colorization but cat is happy with it). Now only colorizing output to console.
• Do we want to support more log destinations other than just console + file? (There's quite a few possibilities that could be integrated without too much work, but which would drag in more dependencies). Tentatively keeping to just console + file pending further modularization of controller.
• Should we assume that the user is responsible for logrotation using tools of their choice, or build support for this directly into the tool using some of the existing transport options there for that? (Note that I haven't yet confirmed that 3rd party logrotation tools don't conflict). Should include test logrotation with logrotate.d
• Is it best to keep logs in UTC like here at the moment, or in the server's local time zone? Should default to local timezone (with possible option for a specified alternate timezone)

[confluence]

* Should I keep the console logging colorized even if writing to something like a file?  (`less` gets confused by the colorization but `cat` is happy with it).

I vote no; it's going to cause problems. It is nice in the console, though.

* Do we want to support more log destinations other than just console + file?  (There's [quite a few possibilities](https://github.com/winstonjs/winston/blob/master/docs/transports.md#winston-transports) that could be integrated without too much work, but which would drag in more dependencies).

I don't think we should bother unless someone explicitly requests it.

* Should we assume that the user is responsible for logrotation using tools of their choice, or build support for this directly into the tool using some of the existing transport options there for that?  (Note that I haven't yet confirmed that 3rd party logrotation tools don't conflict).

I vote yes (to assuming that the user will rotate logs with an external tool). We're already relying on an external tool to create a system service, and this task belongs at the same level.

* Is it best to keep logs in UTC like here at the moment, or in the server's local time zone?

I very strongly vote for the server's local time zone. That's the norm for system logs, and it's pretty frustrating for the CARTA logs to be off by two hours from e.g. the nginx logs.

[veggiesaurus]

I vote yes (to assuming that the user will rotate logs with an external tool). We're already relying on an external tool to create a system service, and this task belongs at the same level.

Agreed. Log rotation is definitely outside of the scope of the log source.

I very strongly vote for the server's local time zone. That's the norm for system logs, and it's pretty frustrating for the CARTA logs to be off by two hours from e.g. the nginx logs.

Yes, I agree, provided we ensure we indicate the timezone in the timestamp :)

I don't think we should bother unless someone explicitly requests it.

In this case, someone is asking for it: @robsimmonds wants it to be connectable to grafana, which should work with winston-loki, or perhaps we can get it to just work with the builtin winston HTTP transport module 🤞🏻

Happy for those to come later though

[daikema]

I don't think we should bother unless someone explicitly requests it.

In this case, someone is asking for it: @robsimmonds wants it to be connectable to grafana, which should work with winston-loki, or perhaps we can get it to just work with the builtin winston HTTP transport module 🤞🏻

I'd gotten the impression that @robsimmonds wanted us to be able support logging to a network endpoint, but wasn't 100% settled on the specific technology. Given that winston supports quite a few options in that regard (and winston-loki doesn't even make the main transports list), I'm leaning towards leaning towards deferring that to later - possibly adding logging to the list of things to be made pluginable.

[daikema]

OK. So this now should be ready for review.

Doc updates are done including an example config for log rotation. Should note that as part of this change I've gone and renamed LogFileTemplate to backendLogFileTemplate which would be a breaking change for those using this option in this their configs as the original name was getting confusing with the controller now having it's own logging options. (Should I make this backwards-compatible, or since this would likely only be encountered by users as part of a new major release would it be OK to leave as is?).

Pull request to the schemas repos with similar updates there I figured I'd save for after some comments on the schema changes already done here to avoid having to revise in a couple of places at same time.

[daikema]

Should maybe also mention that I'm using syslog log levels instead of npm log levels (even though npm log levels are default). If you'd prefer to stick to defaults it should be pretty straightforward to switch.

[daikema]

@veggiesaurus realized that you'd mentioned that "provided we ensure we indicate the timezone in the timestamp :)"

Should note that the updated version logs in the server's local timezone by default but doesn't indicate the timezone in the output. It's also possible to override the timezone in the config file, but if you override the timezone the updated timezone also isn't indicated in the timestamp. Not sure if you want the timezone in place in such cases.

[confluence]

This isn't required and has no default. What happens if it's not specified? If that disables logging to a file, the description should mention it.

[confluence]

Since the backend log file location does have a default, I think it would be good for this to have one as well.

Since the default backend file location is /var/log/carta/username..., I don't love making the default /var/log/carta/controller.log, but it would be nice to keep everything in /var/log/carta/, and none of the alternatives are appealing.

Also, the description should mention that no log rotation is performed by the controller and must be configured separately. Got to the docs; maybe this isn't necessary.

I still think logging to file should be enabled by default, although if rotation is not set up by default perhaps we should discuss this further. I'm concerned that users won't have logging available by default unless they set something up, but having a single file that keeps growing by default is also not good.

[daikema]

Wonder if @veggiesaurus has any thoughts here.

Thus far the controller has solely logged to the console, leaving the remainder up to the user. Here I added "logFile":"/var/log/carta/controller.log", to the example config to emphasize that logging might be useful but otherwise in this respect it behaves similar to prior to the changes in this PR.

But you are right @confluence that the backend logs do have a default, so adding a new default here wouldn't be super-weird or lacking precedent. Had to add a su carta carta to the logrotate example given log file ownership, so figure we sorta want it separated into a directory of its own for log rotation to work nicely. It doesn't sound like you've got a better idea though?

having a single file that keeps growing by default is also not good.

To be fair, at the moment we don't include any example of how to clean up old backend logs so if you have a server that's been running for some time you might end up with a large number of files there. Perhaps we should also add an example cron job that clears backend logs that've been around for, e.g., over 30 days from there?

[confluence]

We can't rename this without bumping the schema version and adding functionality for dealing with older config files (it's a non-backwards-compatible change).

I suggest that we just change the description for now (since there's no name clash), and in a separate issue figure out how to deprecate the old name correctly. This would probably require adding the handling of the fallback name plus a deprecation warning.

[daikema]

Created #234.

Also pushed changes that revert the logFileTemplate -> backendLogFileTemplate for now to make merge-ready.

Addition of backwards compatibility code as I'd suggested here is something that could be done quickly. Still tempted to get the change + backwards compatibility in before the merge as a new major release would seem the ideal time to make something deprecated IMO (@confluence? Would basically need to add a new deprecated schema entry + then a tiny bit of compatibility code to throw a deprecation warning).

[confluence]

If we add a default, we should remove this.

[daikema]

This is now hopefully ready to merge just after CARTAvis/schemas#7 assuming no further change requests (and if I can figure out the git incantations related to submodules).

[confluence]

Minor request for message wording change; otherwise looks good. Please remember to bump the schemas submodule version again after the schemas PR has been merged.