Page MenuHomeFeedback Tracker

Missing timestamps in linux server logs
Feedback, NormalPublic

Description

Timestamps are missing from some error messages in the server's stderr output and log files.

I briefly talked to @dedmen about this in the discord, where I mentioned that I've been seeing entries like such:

Bad conversion: scalar
16:22:01  ➥ Context: 	[] L1 ()
	[] L496 (A3\functions_f\initFunctions.sqf)
        ...
	[] L18 (x\zen\addons\faction_filter\XEH_preStart.sqf)

and

16:22:11 Warning Message: '/' is not a value
No class ''
No ammo class ''
OPTRE_M_ANVIL_4_ARTY: Bad ammo simulation 'shotRocket'

where I would expect to see lines like Bad conversion: scalar and OPTRE_M_ANVIL_4_ARTY: Bad ammo simulation 'shotRocket' having timestamps as they are separate to the content above them in the logs.


There also seems to be missing timestamps on the steam log entries, though I'm not sure whether that's intended or not?
(As I would assume that entries like Setting breakpad minidump AppID = 107410 are not part of the context for the global namespace error, so I feel like they should also be explicitly timestamped, but I'm not sure.)

Global namespace not passed during: false
Global namespace not passed during: false
16:22:26 Error in expression <false>
16:22:26   Error position: <false>
16:22:26   Error Local variable in global space
CApplicationManagerPopulateThread took 0 milliseconds to initialize (will have waited on CAppInfoCacheReadFromDiskThread)
RecordSteamInterfaceCreation (PID 25816): SteamGameServer012 / GameServer
RecordSteamInterfaceCreation (PID 25816): SteamUtils009 / Utils
Setting breakpad minidump AppID = 107410
2023/03/17, 16:22:26 Initializing Steam server - Game Port: 2302, Steam Query Port: 2303
RecordSteamInterfaceCreation (PID 25816): SteamGameServer012 / GameServer
RecordSteamInterfaceCreation (PID 25816): SteamUtils009 / Utils
RecordSteamInterfaceCreation (PID 25816): SteamNetworking005 / Networking
RecordSteamInterfaceCreation (PID 25816): SteamGameServerStats001 / GameServerStats
RecordSteamInterfaceCreation (PID 25816): STEAMHTTP_INTERFACE_VERSION002 / HTTP
RecordSteamInterfaceCreation (PID 25816): STEAMINVENTORY_INTERFACE_V002 / Inventory
RecordSteamInterfaceCreation (PID 25816): STEAMUGC_INTERFACE_VERSION010 / UGC
RecordSteamInterfaceCreation (PID 25816): STEAMAPPS_INTERFACE_VERSION008 / Apps
CAppInfoCacheReadFromDiskThread took 169 milliseconds to initialize

I've attached a quick log file containing the piped out stderr messages of the server. It should contain versions of each of the examples I've used above.

Details

Severity
Minor
Resolution
Open
Reproducibility
Always
Operating System
Linux x64
Operating System Version
Linux Fedora 37 @ Kernel 6.1.18-200.fc37.x86_64
Category
Server
Steps To Reproduce

Run arma3server on linux with the -debug flag set.
I have confirmed this to be reproducible on my end across both the stable and "performance/profiling" binaries.

Additional Information

I was asked to quote the following from the discord for more context:

[14:51]Dedmen (ง •̀_•́)ง: Every separate message in engine, goes through the same code, which should add timestamp per message
[14:51]Dedmen (ง •̀_•́)ง: But what I see here.
The one with timestamp is a warning, all the ones without are Errors
[14:53]Dedmen (ง •̀_•́)ง: But, looking at Error code, that forwards the message to the warning code, which adds the timestamp 🤔
[14:53]Dedmen (ง •̀_•́)ง: dunno why that wouldn't  happen 🤔
[14:54]Dedmen (ง •̀_•́)ง: Unless diag binary, but you're not doing that I assume
[14:54]Dedmen (ง •̀_•́)ง: And, unless linux :harold:
[14:55]Dedmen (ง •̀_•́)ง: On Linux, Specifically Error messages (not warnings) don't print timestamp, that's a bug

Event Timeline

dedmen set Ref Ticket to AIII-55611.Mar 17 2023, 5:11 PM
dedmen changed the task status from New to Feedback.Mar 27 2023, 3:00 PM