fox-it
MSSQL incorrect timestamp parsing
I have a raw MSSQL ERRORLOG file. Parsing this file using the existing MSSQL plugin results in an issue with the timestamps. The timestamps do not match the message as they do in the raw log.
$ rg xp_cmdshell fs/C\:/Program\ Files/Microsoft\ SQL\ Server/MSSQL15.MSSQLSERVER/MSSQL/LOG/ERRORLOG
4987:2025-09-15 09:49:56.54 rpid03 SQL Server blocked access to procedure 'sys.xp_cmdshell' of component 'xp_cmdshell' because this component is turned off as part of the security configuration for this server. A system administrator can enable the use of 'xp_cmdshell' by using sp_configure. For more information about enabling 'xp_cmdshell', search for 'xp_cmdshell' in SQL Server Books Online.
4989:2025-09-15 09:50:37.20 rpid03 Configuration option 'xp_cmdshell' changed from 0 to 1. Run the RECONFIGURE statement to install.
4994:2025-09-15 11:26:01.31 rpid03 Configuration option 'xp_cmdshell' changed from 1 to 0. Run the RECONFIGURE statement to install.
$ target-query -f mssql.errorlog TARGET > mssql_errorlog.rec
$ rdump mssql_errorlog.rec ~~f '{ts} -~~> {message}' | grep xp_cmdshell
2025-09-15 09:50:28.880000+00:00 --> SQL Server blocked access to procedure 'sys.xp_cmdshell' of component 'xp_cmdshell' because this component is turned off as part of the security configuration for this server. A system administrator can enable the use of 'xp_cmdshell' by using sp_configure. For more information about enabling 'xp_cmdshell', search for 'xp_cmdshell' in SQL Server Books Online.
2025-09-15 10:15:02.320000+00:00 --> Configuration option 'xp_cmdshell' changed from 0 to 1. Run the RECONFIGURE statement to install.
2025-09-15 11:26:06.290000+00:00 --> Configuration option 'xp_cmdshell' changed from 1 to 0. Run the RECONFIGURE statement to install.
Thank you for your bug report @qmadev
The timestamp of entry N+1 is being assigned to the message of entry N.
This is because the parser only processes a log entry after it finds the timestamp for the next entry by looking ahead.
Already have a fix in mind?
I basically gave it no thought and just created the issue. I'll hopefully have some time to fix it at the end of the month.
Untested, but roughly something like
for errorlog in log_path.glob(self.FILE_GLOB):
fh = errorlog.open(mode="rt", encoding="utf-16", errors="surrogateescape")
# Variables to hold the record we are currently building
current_ts = None
current_buf = ""
for line in fh:
# Check if the line marks the start of a new log entry
if ts_match := RE_TIMESTAMP_PATTERN.match(line):
if current_ts:
yield MssqlErrorlogRecord(
...
)
# --- Now, start the NEW record ---
current_ts = ...
current_buf = line
else:
if current_buf: # Ensure we don't add to an empty buffer before the first timestamp
current_buf += line
# --- Yield the very last record in the file ---
if current_ts and current_buf:
yield MssqlErrorlogRecord(
...
)
Don't know when our PO schedules this, but would be great if this helps you.
