Logging: Include timestamps in messages by default

[fwcd]

This is a small patch that updates the log file format to include hh:mm:ss.zzz timestamps.

Timestamps are particularly valuable for understanding timing-related issues and the program's execution in general, and the latter would get them included in user-submitted reports. The only drawback I see is that this would result in slightly larger log files.

[daschuer]

I think when I remember correct, the timestamp is not included intentionally.

I have no strong opinion here, but I cannot remember a single case when reading users mixxx.log where I wished it has a timestamp. On the other hand I can remember discussion about complains of the file size and the default log level. It has been proposed to not write debug entries into the file.
When I would have a choice to select timestamps or debug messages, I would select the later.

Can you describe your use case where timestamps are helpful? Maybe we can target it differently.

I can also confirm that adding timestamps conditionally via QT_MESSAGE_FORMAT is too complicated.

[Swiftb0y]

• The log file format to include yyyy-MM-dd hh:mm:ss.zzzz timestamps
  • This cannot be customized, as far as I understand.

Why would that be the case? As long as the format passed is valid, it could be altered on every call as far as I understand.

[ronso0]

Just my 2 cents:
never really needed timestamps either, but if this is merged I'd prefer to allow hiding it from the log stream. For debugging I often use a terminal & Mixxx window side by and short log lines are very welcome to avoid line-wrap.

[Swiftb0y]

never really needed timestamps either, but if this is merged I'd prefer to allow hiding it from the log stream. For debugging I often use a terminal & Mixxx window side by and short log lines are very welcome to avoid line-wrap.

This should cover your usecase/workflow, right?

This can be customized with QT_MESSAGE_FORMAT, but I would argue that timestamps are useful enough to be a sensible default

[fwcd]

Can you describe your use case where timestamps are helpful? Maybe we can target it differently.

Including the timestamps is quite helpful in understanding the flow of the program, without them I wouldn't know if something happened in quick succession or hours apart. This can be surprisingly useful for debugging (which I make heavy use of as I'm currently debugging a pretty hard-to-reproduce freeze...)

Also while I agree that the log size shouldn't be dismissed, e.g. the size of analyzed waveforms generally dwarfs even the biggest log files which I've seen. (Most of those files are a few MB at maximum, the only one that's a few hundreds of MB large was one that included very heavy trace logging, i.e. hundreds of lines per second for several hours).

never really needed timestamps either, but if this is merged I'd prefer to allow hiding it from the log stream. For debugging I often use a terminal & Mixxx window side by and short log lines are very welcome to avoid line-wrap.

As @Swiftb0y said, this can be customized with QT_MESSAGE_FORMAT and I'd definitely be open for suggestions regarding the default. My main focus would be more on the mixxx.log anyway, since those files actually benefit from including some extra information due to their use in diagnosing issues.

Why would that be the case? As long as the format passed is valid, it could be altered on every call as far as I understand.

Perhaps I don't quite understand what you mean, I was referring to that this cannot be customized at runtime (as opposed to the stdout format).

[ronso0]

Can someone point me to info about QT_MESSAGE_FORMAT, I just don't find that literal string online. Thanks!

[fwcd]

Ah, my mistake, it was QT_MESSAGE_PATTERN:

mixxx/src/util/logging.cpp

Lines 66 to 74 in dfde28d

	// Note:
	// you can customize this pattern by starting Mixxx with
	// QT_MESSAGE_PATTERN="%{message}" mixxx
	// For debugging timing related issues
	// QT_MESSAGE_PATTERN="%{time yyyyMMdd h:mm:ss.zzz} %{type} [{{threadname}}] %{message}"
	// Or for for finding the origin (in Debug builds)
	// QT_MESSAGE_PATTERN="%{type} [{{threadname}}] %{file}:%{line} %{message}"
	// QT_MESSAGE_PATTERN="%{type} [{{threadname}}] %{function} %{message}"
	// TODO: Adjust the default format and messages and collect file and function info in release builds as well.

[Swiftb0y]

Perhaps I don't quite understand what you mean, I was referring to that this cannot be customized at runtime (as opposed to the stdout format).

Why couldn't it be customized at runtime? I mean not by Qt, but the string is built from runtime, so instead of hardcoding "hh:mm:ss.zzzz" we could just pass something in we got from an env variable or cli flag instead.

[fwcd]

This seems to be an intentional decision (to make bug reports more uniform, I would assume):

mixxx/src/util/logging.cpp

Lines 118 to 119 in dfde28d

	/// Format message for writing into log file (ignores QT_MESSAGE_PATTERN,
	/// because logfiles should have a fixed format).

[Swiftb0y]

This seems to be an intentional decision (to make bug reports more uniform, I would assume):

Ah right. Let me clarify: I thought you said that it was technically impossible because of Qt API restrictions (or similar). Whether we should make that modifiable is a different question. I agree with the current code that we should hardcode it to keep it consistent.

[Swiftb0y]

LGTM, but I won't merge until the current discussions with the other team members have been explicitly resolved.

[daschuer]

I can also confirm the line width issue. How about not making this a default, but making it easy to enable.
Currently we have the issue that you need to compose the desired message alone when you just want to have a timestamp for a specific problem. That is hard on our desk and even harder to do it remote with a non tech user.

What could be the alternative? A command line switch? A preferences option?

[fwcd]

Wdyt about only including timestamps in the mixxx.log for now? Technical users can use QT_MESSAGE_PATTERN to enable them anyway and non-technical users can always send us their mixxx.log?

[daschuer]

That works for me.

[Swiftb0y]

LGTM otherwise. Would you do me the favor and squash everything into a single commit?

[Swiftb0y]

LGTM. Waiting for CI. Any1 else wanting to sign off?