Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging file rotation renames old files with the current date rather than the date they were created on #44816

Open
CitrusWire opened this issue Dec 30, 2020 · 5 comments

Comments

@CitrusWire
Copy link

Godot version:
3.2.3

OS/device including version:
Win 7

Issue description:
When godot does log rotation, it renames godot.log and appends the ISO timestamp:
Problem is, the ISO timestamp isn't the one you'd expect.

The godot.log file from the last run is renamed and given a name with the timestamp of right now (as in, this run). This is very odd and not at all the timestamp you'd expect, and the logs are now misnamed.

I'd expect the godot.log from the last run to be renamed with either:

  • Timestamp it was originally Created (this is how it's usually done)
  • Timestamp it was last Modified

I've never seen timestamped logs use the timestamp they were renamed (what's happening now).

(Also, rather than simply renaming the file, it looks like the rotation actually creates an entirely new file so you lose the original file timestamp metadata. I'd suggest that's another part of this bug too (possibly even the cause).)

Steps to reproduce:

  • Enable file logging
  • Run application and stop it
  • Wait 1 or more minutes
  • Run application - the first godot.log file will have been renamed and will have the timestamp that you started this run.

Minimal reproduction project:
n/a

@Calinou
Copy link
Member

Calinou commented Dec 30, 2020

Timestamp it was originally Created (this is how it's usually done)

The issue is that we can't know for certain when the log file was originally created. Relying on file creation dates can be unreliable since some operating systems may not report them correctly or at all (depending on filesystem settings).

@Calinou Calinou changed the title Logging file rotation dates are wrong Logging file rotation will rename old files with the current date rather than the date they were created on Dec 30, 2020
@Calinou Calinou changed the title Logging file rotation will rename old files with the current date rather than the date they were created on Logging file rotation renames old files with the current date rather than the date they were created on Dec 30, 2020
@CitrusWire
Copy link
Author

Timestamp it was originally Created (this is how it's usually done)

The issue is that we can't know for certain when the log file was originally created. Relying on file creation dates can be unreliable since some operating systems may not report them correctly or at all (depending on filesystem settings).

Makes sense, though that's a problem with the host filesystem then. Unless it's so broken everything is 1970-01-01 (at which point the OS should consider itself lucky that programs behave predictably at all ;-) ), I'd expect it to still be different and more accurate timestamps per file than the current system which is misleadingly wrong on all filesystems.

Alternatively I'd suggest what I think would make more sense for log rotation (it is the norm in the rotated logs I usually see):

  • When originally creating the log file, use the timestamp in its name. There's never a godot.log, only a series of godot-ISO-TIME_STAMP.log files.
    As a bonus this also solves the "losing file timestamp metadata" issue as there's never any renaming.

(I appreciate why you renamed the issue and I did consider not using "wrong". "Wrong" wasn't meant antagonistically; it's empirically using the wrong timestamp for the log; none of the contents of the log relate to the timestamp used.)

@Calinou
Copy link
Member

Calinou commented Dec 30, 2020

  • When originally creating the log file, use the timestamp in its name. There's never a godot.log, only a series of godot-ISO-TIME_STAMP.log files.
    As a bonus this also solves the "losing file timestamp metadata" issue as there's never any renaming.

Indeed, I think this is a better idea. The downside is that you no longer have a "latest" log file with a fixed file name, but I doubt this is an issue in practice. (Maybe this could still be done if you define the maximum number of log files to 1.)

@CitrusWire
Copy link
Author

The downside is that you no longer have a "latest" log file with a fixed file name, but I doubt this is an issue in practice.

I did consider this, though doubt it's a real issue. Especially given godot is a game engine and not something you're likely to find in a devops-y enviroment where ease-of-scriptable-access is that important.

@pwnorbitals
Copy link

Could still reproduce today. Also, when editing log output path by hand, it spams the in-editor log window with some "Set log_path" debugging messages. Fix for the timestamp is core/io/logger.cpp l164, and use FileAccess::get_modified_time (simple fix but doesn't use the creation time) or add a FileAccess static method to retrieve creation time (which itself requires adding a method to FileAccessNetwork in core/io/file_access_network.cpp). Not sure where the debug spam comes from, though

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants