Fixing data stage spam

[Rseding91]

This has been bugging me since the ability to log() during the data stage was added and mostly it's my fault for not accounting for it when it was first added.

Ever since log() was made available during the data stage in Factorio modding mods have been spamming log files. It's so bad that log files end up 10s of thousands of lines adding up to several megabytes worth of useless nothing.

Today while talking with about a bug with another dev it was brought up again and we decided that we want to try to fix it.

My initial plan - unless something better is thought up - is to make log() during data stage do nothing unless you also have --enable-data-log set through the command line. I specifically don't want to make it a config option because it should always be a conscious decision to have it enabled at any point and not something you enable in the config and forget it's enabled.

Another plan (by Bilka): record everything sent through log() during the data stage and if an error is triggered during the data stage or by scenarios then actually write it to the log file. This would also have the --enable-data-log option to force everything to be written instead of buffered.

[DaveMcW]

Why not have log() output to a different file?

[Nexela]

I would love a write_file() in the data stage and I wouldn't have to log!

[Sunnova]

please add enable-data-log to the config.ini file instead of the command line, true or false.

[Bilka]

This will make mod authors lose viable info when asking for log files from users such as "x mod decided to delete your tile prototypes" which is currently being logged by mod x. For this, and similar "fixing users bugs" reasons, I would prefer to not do the proposed change.

Instead, add something like write file to allow proper debugging without log(), or even a special debug log function that needs the command line parameter that you describe. In the end, you cannot change shitty mods/mod authors that spam logs, they will/can do the same in the control stage. I'd even say that by adding the command line parameter, you make log() spam completely ignorable to mod authors because "it has a command line option". So anyone who has the option on will have even worse log files than before. The annoying overuse of log_debug and ""informational asserts"" in the source code is an example of that dynamic.

[keyboardhack]

Maybe write log() to another file(like factorio-current-mods.log) when the game is running and when the game closes/crashes add the log file to the end of the factorio-current.log file. That way the log is still part of the factorio-current.log file but you don't have to look at it unless you scroll down to it. Why append the log to the end of the file? Because uploading two different files is apparently more difficult than uploading one(always assume the end user is stupid) and a mod author may need it to fix any issues with the mod.

[darkfrei]

We have script-output folder, why we cannot write the log here?
It makes vanilla log file much lighter and in this way we can make mod parts semi-automatically, for example export locale draft to the file, that can be used as draft for locale for this mod.

[eradicator]

My initial plan - unless something better is thought up - is to make log() during data stage do nothing unless you also have --enable-data-log set through the command line. I specifically don't want to make it a config option because it should always be a conscious decision to have it enabled at any point and not something you enable in the config and forget it's enabled.

People will put that into batch files, shortcuts, or steam command line options when the first mod author asks them to do it and then forget about it anyway.

Another plan (by Bilka): record everything sent through log() during the data stage and if an error is triggered during the data stage or by scenarios then actually write it to the log file. This would also have the --enable-data-log option to force everything to be written instead of buffered.

What if someone just wants to look at their mod log without any error happening? Besides it's unexpected behavior to have the log suddenly appear from "nowhere". And the order would probably look weird in a terminal.

I would love a write_file() in the data stage and I wouldn't have to log!

This, for so many reasons. Writefile should just be always accessible globally in all stages. Having it only *inside* of events is a major limitation. It's not a complete replacement for logging though, when i tell users "send me the log" i don't want to teach them how to find yet another file buried somewhere in /script-output.

This will make mod authors lose viable info when asking for log files from users such as "x mod decided to delete your tile prototypes" which is currently being logged by mod x. For this, and similar "fixing users bugs" reasons, I would prefer to not do the proposed change.

+1000000
The only point i have logging enabled at all in user-builds is bug fixing. I even added a mod-setting to only enable full logging if something really bad happens, and by default it only logs important things. On my dev-build i don't even use log but print() instead. But obviously i can't ask users to run with an attached terminal.

Maybe write log() to another file(like factorio-current-mods.log)

+1. Just split it off if you don't want it, but don't kill it for everyone else. Or you could just mark mod made log() entries with some (possibly invisible) control character so you can easily RegEx delete them.

[Deadlock989]

This will make mod authors lose viable info when asking for log files from users such as "x mod decided to delete your tile prototypes" which is currently being logged by mod x. For this, and similar "fixing users bugs" reasons, I would prefer to not do the proposed change.

Instead, add something like write file to allow proper debugging without log(), or even a special debug log function that needs the command line parameter that you describe. In the end, you cannot change shitty mods/mod authors that spam logs, they will/can do the same in the control stage. I'd even say that by adding the command line parameter, you make log() spam completely ignorable to mod authors because "it has a command line option". So anyone who has the option on will have even worse log files than before. The annoying overuse of log_debug and ""informational asserts"" in the source code is an example of that dynamic.

+1.

[mrvn]

And often enough I wondered about something mid game and switched to looking at the logs. Now I have to save the game, quit, start with --enable-logs, load the game, hope the bug still or again happens and then remember to start factorio without --enable-logs again next time.

I like the suggestion to log mod output to individual files per mod.

[Cadde]

Why not do this?

Code: Select all

...
Data stage:
{
  log()
  log()
  log()
  log()
  log()
  log()
  ...
}

This way, any log() output is bracketed in the data stage so you can collapse the brackets in your text editor or whatever else you use.

EDIT: Won't solve the 10 MB file issue though.
Perhaps have a limit on how much log output a single mod is allowed to do in the data stage and use your aforementioned command line switch to remove the limit.

[eduran]

Mods spamming the log file are annoying for sure, but any solution to that would also hit responsible mod authors who deactivate logging for their release builds. Also, out of curiosity: why is it only data-stage spam that you are worried about and not control stage logging?

If you do change it, I vote for one separate log file for mods (e.g. factorio-current-mod.log).

[darkfrei]

Also, out of curiosity: why is it only data-stage spam that you are worried about and not control stage logging?

While mod authors can use LuaGameScript.write_file for big data.

[Deadlock989]

If you do change it, I vote for one separate log file for mods (e.g. factorio-current-mod.log).

+1.

[Rseding91]

Also, out of curiosity: why is it only data-stage spam that you are worried about and not control stage logging?

Data stage spam is incredibly common (people just log data.raw or portions of it). Runtime control.lua logging doesn't have a super easy huge table to log and so (so far) hasn't been a problem.

[eradicator]

Also, out of curiosity: why is it only data-stage spam that you are worried about and not control stage logging?

Data stage spam is incredibly common (people just log data.raw or portions of it). Runtime control.lua logging doesn't have a super easy huge table to log and so (so far) hasn't been a problem.

If that is the main problem an always-available write_file() sounds like the best solution. "People" would migrate on their own because the data dump would be much easier to read without the log decorations.

[Qon]

If that is the main problem an always-available write_file() sounds like the best solution. "People" would migrate on their own because the data dump would be much easier to read without the log decorations.

log() is also simpler to write. No file name, no append flag, so trivial that you don't need to look up documentation, shorter name and less to write when you just want to quickly debug something and dump some data. Just wrap the x in log() and you can see its value. And then they forget to remove it or don't care.

Maybe make log write to the mods own log file and introduce a new function that lets us actually log to factorio-current.log with a much longer name. Something like

Code: Select all

log_to_factorio_current_but_only_for_critical_information_and_not_for_data_dumps_and_remember_to_remove_any_needless_use_of_it_for_release_or_Rseding91_will_be_disappointed()

is a good name. Until you put it in another variable with a shorter name... But at least there would be a reminder that you would be forced to see at least once before you use it. So that when I get factorio-current.log I actually get the critical data and don't have to ask them to also submit another file (which will be overwritten by then) or to use command line options and tell them to reproduce the bug again, which they don't want to or can't do.

[Optera]

When I need to track errors between LTN and mods subscribing to LTN events having each write to a separate file makes it incredibly hard to get a full picture of what went on.
The same is true for 3rd or 4th degree mods patching another in data stage.

If anything we'd need to log more to get a complete picture. We will end up with every single of these mods dumping data.raw before and after they are done, maybe even several times in between.
Even 10MB for factorio-current.log can be compressed to some kB in an archive. The disk IO of each mod dumping everything into its own file on the other had will get insane.

Instead of making life harder on responsible authors add a way to get rid of crappy mods. Could be as simple as adding a thumbs up/down button in the portal and in game so we can vote badly written mods out.

[darkfrei]

Is it possible to use it as log(data, filename)? It can be same Factorio/factorio-current.log or if filename is not nil then Factorio/logs/filename.log

[darkfrei]

Instead of making life harder on responsible authors add a way to get rid of crappy mods. Could be as simple as adding a thumbs up/down button in the portal and in game so we can vote badly written mods out.

The voting "like-dislike" is the worst solution to get the mod authors right feedback. It's always better to write a message and say what is actually goes wrong with his mod.
If someone has made the first version and it was not good enough, he can make update and it works perfectly. Are old dislikes can give the right information about mod quality?
How many mods was perfect by first release?