Include milliseconds in logging timestamps
Description
Include milliseconds in logging timestamps and improve formatting while at it. Should now give better idea how long individual steps take (shader compilation, encoder probing, etc).
Screenshot
Before
[2024:08:04:22:33:15]: Info: Sunshine version: 0.0.0.f8b0be1e
After
[2024-08-04 22:33:15.623] Info: Sunshine version: 0.0.0.f8b0be1e
Issues Fixed or Closed
Type of Change
- [ ] Bug fix (non-breaking change which fixes an issue)
- [x] New feature (non-breaking change which adds functionality)
- [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected)
- [ ] Dependency update (updates to dependencies)
- [ ] Documentation update (changes to documentation)
- [ ] Repository update (changes to repository files, e.g.
.github/...)
Checklist
- [x] My code follows the style guidelines of this project
- [x] I have performed a self-review of my own code
- [x] I have commented my code, particularly in hard-to-understand areas
- [x] I have added or updated the in code docstring/documentation-blocks for new or existing methods/components
If we're going to adjust the logging format, can we improve the readability a little more?
I'm not an expert on boost logging, but can we do something like this?
2024-08-04 22:33:15.623 - INFO :: <module/file that called the message... or the thread> : <the message>
It's possible, but in my opinion we shouldn't.
It will
- add quite a bit of informational bloat
- break message alignment
- be entirely useless for users
- be not very useful for us (copy-pasting and searching the codebase for message keywords is near instantaneous and hasn't failed me once for sunshine)
So yeah. Small changes that objectively improve the situation (conventional date separating symbols, removing needless ':') I can do. Large subjective changes, I'd rather not.
I agree with your points, I was just thinking it would allow us to not have to search and we could go directly the point in the code... I guess it's not incredibly value added, unless the message is from outside of Sunshine's codebase.
I would like the log format to be like this though if you could.
2024-08-04 22:33:15.623 - INFO :: <the message>
I would like the log format to be like this though if you could.
2024-08-04 22:33:15.623 - INFO :: <the message>
No strong opinion on this, but I don't want it to be traced to my commit since I have nothing to do with the decision.
I've updated this PR leaving only the timestamp change. The rest can be done outside without any deep c++ knowledge. https://github.com/ns6089/Sunshine/blob/4dc34b0e670cbad5577cd2bce8d83b2a5e9a833a/src/logging.cpp#L77-L92 https://github.com/ns6089/Sunshine/blob/4dc34b0e670cbad5577cd2bce8d83b2a5e9a833a/src/logging.cpp#L103 https://github.com/ns6089/Sunshine/blob/4dc34b0e670cbad5577cd2bce8d83b2a5e9a833a/src_assets/common/assets/web/index.html#L145
Codecov Report
All modified and coverable lines are covered by tests :white_check_mark:
Project coverage is 9.68%. Comparing base (
04df80f) to head (5ba5065). Report is 138 commits behind head on master.
Additional details and impacted files
@@ Coverage Diff @@
## master #2963 +/- ##
=========================================
+ Coverage 9.67% 9.68% +0.01%
=========================================
Files 97 97
Lines 17526 17528 +2
Branches 8199 8200 +1
=========================================
+ Hits 1696 1698 +2
+ Misses 13052 12993 -59
- Partials 2778 2837 +59
| Flag | Coverage Δ | |
|---|---|---|
| Linux | 7.19% <85.71%> (+0.01%) |
:arrow_up: |
| Windows | 5.11% <100.00%> (+0.01%) |
:arrow_up: |
| macOS-12 | 10.37% <71.42%> (+0.03%) |
:arrow_up: |
| macOS-13 | 10.26% <71.42%> (+0.02%) |
:arrow_up: |
| macOS-14 | 10.58% <71.42%> (+0.02%) |
:arrow_up: |
Flags with carried forward coverage won't be shown. Click here to find out more.
| Files with missing lines | Coverage Δ | |
|---|---|---|
| src/logging.cpp | 81.30% <100.00%> (+0.35%) |
:arrow_up: |
Added an #include statement. It should fix failing builds on some platforms (hopefully).