inconsistent timestamps in the log file

[ajm-ska]

Describe the bug
Myself and @kswang1029 have noticed that the timestamps in the log file are inconsistent. It is clear in the following example:

[2022-07-15 12:07:27.873] [CARTA] [info] Session 671617008 [127.0.0.1] Connected. Num sessions: 1
2022-07-15 04:07:40	INFO	FITSCoordinateUtil::fromFITSHeader	passing empty or nonexistant spectral Coordinate axis
[2022-07-15 12:07:43.281] [CARTA] [debug] Updated 1 preferences

It appears carta-casacore is writing in UTC time, but carta-backend is writing in local time, in this case UTC+08:00.

To Reproduce
Steps to reproduce the behavior:

1. Change your computer timezone to one that is not UTC time.
2. Use CARTA for a bit.
3. Check the log file.
4. Note that some time stamps in the log file use UTC time and others use UTC+timezone.

Expected behavior
All time stamps in the log file should be consistent. Perhaps local time (UTC+timezone) for personal desktop versions of CARTA?
(I'm not sure if UTC time would be preferred for carta-controller?)

Platform info (please complete the following information):

• OS [e.g. macOS Monterey]: macOS Monterey
• Browser [e.g. chrome, safari, electron app]: Chrome
• Browser version [e.g. 22]: 103
• Backend branch [e.g. dev, v3b2 release]: dev
• Frontend branch [e.g. dev, v3b2 release]: dev

Additional context
It would be good if the format of the timestamps were consistent too.
Note the 2nd line does not use square brackets.
[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO
Would this need to be a carta-casacore change?

[veggiesaurus]

@pford do you know whether we can pass some parameter to casacore in order to adjust the logging format?

[pford]

casacore::LogMessage has a set format which includes the time string from GMT, and there is no way to use local time without a casacore change. However, you can set spdlog to use UTC instead of local time.

On the casacore side, most of the casacore logging is info and warnings, and any SEVERE-priority messages "will often be followed by a thrown exception" according to the header (which can and should be caught and handled by carta). If the casacore logging is unnecessary we could set the casacore log priority to SEVERE (would still be in UTC but fewer messages), or throw away the messages using casacore::NullLogSink.

[kswang1029]

I wonder if we should set spdlog to UTC as well? It is possible that the CARTA server is not at the same time zone as the user is. So it is possible that the user needs to deal with three timezones, user timezone, CARTA backend timezone, and UTC from casacore.

[ajm-ska]

I vote for having spdlog report in UTC time. It sounds like the easiest solution.

I'm not sure about fewer casacore messages. On one hand, "WARN" messages from a single image could take up hundreds of log file lines, but I'm not sure if they could be important for debugging CARTA?

As for the format of the timestamps e.g.

[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO

Originally I was naively thinking that the casacore style log could be changed to the carta-backend/spdlog style. But maybe we could more easily change the carta-backend/spdlog style to casacore style instead?
i.e. Remove the square brackets and the millisecond timing.
Then it would be consistent with the casacore style. What do you think?
(It is just a suggestion. I know the current format was most likely thoroughly discussed before. Maybe the square brackets are now the proper way to parse log files. Maybe millisecond timing is important for debugging?)

[kswang1029]

@pford @veggiesaurus @confluence if it is a one-linear to set spdlog in UTC, shall we get this in in v3-stable?

[markccchiang]

I think we can just change this code line in Logger.h as

formatter_(details::make_unique<spdlog::pattern_formatter>(pattern_time_type::utc)) {

[kswang1029]

I think we can just change this code line in Logger.h as

formatter_(details::make_unique<spdlog::pattern_formatter>(pattern_time_type::utc)) {

thanks for checking, would you make a PR then?

[ajm-ska]

As for the format of the timestamps e.g.

[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO

Originally I was naively thinking that the casacore style log could be changed to the carta-backend/spdlog style. But maybe we could more easily change the carta-backend/spdlog style to casacore style instead? i.e. Remove the square brackets and the millisecond timing. Then it would be consistent with the casacore style. What do you think? (It is just a suggestion. I know the current format was most likely thoroughly discussed before. Maybe the square brackets are now the proper way to parse log files. Maybe millisecond timing is important for debugging?)

@kswang1029 What is your opinion about the different formats of the time stamps?

[kswang1029]

if we need a casacore update to show the timestamp down to millisecond, I suggest we handle in later (v4). But if it is not possible, then I am fine with it in my pov and open to other opinions.

[ajm-ska]

if we need a casacore update to show the timestamp down to millisecond, I suggest we handle in later (v4). But if it is not possible, then I am fine with it in my pov and open to other opinions.

Do we need carta-backend/spdlog to show millisecond timestamps?

[kswang1029]

if we need a casacore update to show the timestamp down to millisecond, I suggest we handle in later (v4). But if it is not possible, then I am fine with it in my pov and open to other opinions.

Do we need carta-backend/spdlog to show millisecond timestamps?

I am more inclined to have millisecond timestamps as such would be handy when we need to debug.

[ajm-ska]

@kswang1029 OK. One more question; What is your opinion on the square brackets?
spdlog shows square brackets, casacore has no brackets.

[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO

[kswang1029]

@kswang1029 OK. One more question; What is your opinion on the square brackets? spdlog shows square brackets, casacore has no brackets.

[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO

better readability with [ ] in my pov. I don't have a preference on the consistency here as currently it is handy to tell which part is from casacore.

[veggiesaurus]

@kswang1029 OK. One more question; What is your opinion on the square brackets? spdlog shows square brackets, casacore has no brackets.

[2022-07-15 12:07:27.873] [CARTA]
2022-07-15 04:07:40 INFO

I think our goal should be to have all cassacore messages piped through our logging code, so that we have things like
[2022-07-15 12:07:27.831] [casacore] INFO.