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

Reduce debug.log file size by folding consecutive identical errors #51791

Merged
merged 9 commits into from
Sep 23, 2021

Conversation

OrenAudeles
Copy link
Contributor

Summary

Bugfixes "Reduce debug.log file size by folding consecutive identical errors"

Purpose of change

Should Fix #50017 without requiring the user to modify file permissions. File size of debug.log is unbounded and in the worst case may grow uncontrollably until storage is full.

Describe the solution

This PR does two things to mitigate the issue.

  1. Folds identical errors as much as possible by tracking the unique information of an error (filename, line, function, error message ) and increments a counter if these are identical AND the newest error is within a 100ms window following the previous error. 100ms is a lot of time for a computer, so if the threshold is exceeded it is probably unique enough to deserve its own error line.
  2. Kills program execution at 10k consecutive identical errors. Combined with the 100ms threshold between errors if this threshold is reached something has probably gone horribly wrong and the program has not been able to recover gracefully. 10k was picked to reduce the chance for a false positive.

Describe alternatives you've considered

Mostly readability alternatives for folding. Considered not adding in the killswitch, but if the program is repeatedly erroring on the same line without end the user will end up forcing execution to halt anyway. Considered using a lower value for the killswitch.

Testing

Added calls to debugmsg in loops to see how the folding looks. Used debug menu to force crash the game to make sure the folding is output properly.

Additional context

https://media.discordapp.net/attachments/675502002230394880/890078801176965160/unknown.png

timestamp for repeated error folding group is that of the last folded
error
timeout is currently hardcoded to 100ms. If another repeated error is
registered that would be folded but is >100ms after the previous error
it starts a new folding group
killswitch at 10k repetitions should prevent false positives
use cata_fatal to abort.
It's a little easier to read the log as `[First]<folded>[Last]` than
`[First]<folded with last timestamp>`
Need to test folding output during deinit and DebugLog, made a function
to remove repetition.
@BrettDong BrettDong added the [C++] Changes (can be) made in C++. Previously named `Code` label Sep 22, 2021
@Qrox
Copy link
Contributor

Qrox commented Sep 22, 2021

if the program is repeatedly erroring on the same line without end the user will end up forcing execution to halt anyway

That is not necessarily true. For example, during a player activity, a debug message may be triggered repeatedly and may exceed 10 times a second, but the game does not necessarily freeze (the user can ignore the message and continue playing).

@OrenAudeles
Copy link
Contributor Author

That is not necessarily true. For example, during a player activity, a debug message may be triggered repeatedly and may exceed 10 times a second, but the game does not necessarily freeze (the user can ignore the message and continue playing).

okay, I'll grant that as plausible. Part of why I made the threshold so high is to minimize the chance for false positives. Two ways forward if false positives are encountered. Raise the threshold by another factor of 10 to make it less likely, and tighten to temporal threshold from 100ms to something shorter.

If a player does get caught by the killswitch they should probably file a bug report. 10k repetitions of the exact same error in a short period of time is a problem that needs solving on our end.

@Qrox
Copy link
Contributor

Qrox commented Sep 22, 2021

Maybe we can just ask the player to file a bug report in that case instead of crashing the game. (By showing another debug message, for example)

@OrenAudeles
Copy link
Contributor Author

Players are more likely to file reports when their game crashes. If they can ignore it they will ignore it. If it generates too many false positives instead of catching the absurd loops that were bloating the debug log by gigabytes then it can be dealt with then.

I could also change the folding timeout mechanism from its current 100ms between messages to time threshold over all repetitions which may be able to handle this better. 10k+ identical errors over a few seconds may be more indicative of an unrecoverable loop than what is likely to occur with player_activity generated errors.

@actual-nh actual-nh added the Code: Debug Debugging and troubleshooting the game, also includes the debug menu label Sep 22, 2021
@kevingranade
Copy link
Member

I agree crashing is excessive, just escalating to a popup with clear directions to report the issue is as far as we should go.

src/debug.cpp Outdated

// Yell at user to file a bug report if we get too high repetition count
if( rep_folder.repeat_count > repetition_folder::repetition_threshold ) {
debugmsg( "Excessive error repetition detected. Please file a bug report at https://github.com/CleverRaven/Cataclysm-DDA/issues" );
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Calling debugmsg recursively here might have unintended side-effects. I suggest prepending this line to the original message instead. Might need to add a new flag to debug_error_prompt and use it in the message key to force display the error when the original error was ignored. This also has the benefit of showing the actual repeating error in the debug message.

Copy link
Contributor Author

@OrenAudeles OrenAudeles Sep 23, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Probably the correct move. I'll modify to prepend the original message.
The excessive repetitions error doesn't serve much use going into debug.log but it would be useful as an error prompt. The excessive repetitions will become apparent when reading the log and an entry for that purpose doesn't add information.
An unintended consequence for calling debugmsg here I can see at the moment is for a degenerate case where a single error is repeated millions of times. This will generate folded repetition groups of

[ERROR] fold begin
error fold 10k
[ERROR] fold end
excessive repetition error

and do so a large number of times. It will save some space in debug.log but it will become less readable as a result. It would be better to just output the prompt and skip directly logging it.

The simplest change would be to move this test down to prompt generation and make the test
if( ( rep_folder.repeat_count % repetition_folder::repetition_threshold ) == 0 ) { ... }
and generate a standard ignorable prompt or a forced prompt. If there is prompt forcing via flag would need to alter both debug_error_prompt and replay_buffered_debugmsg_prompts to handle the flag.
A forced, unignorable prompt would interrupt the player frequently with the prompt in a degenerate case and is likely to generate some kind of bug report here, or questions on discord or reddit which can then be used to further prompt a bug report.

Next commit:

  1. Change repetition error into prompt generation so as to not prematurely end existing folds (primary PR goal)
  2. Add in original error message to prompt for readability

For now I will not add in forced prompts. For now if the user wants to ignore the error they will be able to. Can be future work in a future PR if it isn't immediately required.
Ended up adding in forced prompts to ensure that the user does see the prompt once per set of excessive repetitions.

As logged error the excessive repetition error causes breaks in folds
which make debug.log less clear while reading, and does not add information
Forced prompting once excess threshold is reached will prompt once per
excessive repetition set.
@kevingranade kevingranade merged commit ca9791c into CleverRaven:master Sep 23, 2021
I-am-Erk added a commit to I-am-Erk/Cataclysm-DDA that referenced this pull request Sep 23, 2021
* reorganized to support expansion

* reorganized to support expansion

* removed sentences that shouldn't be there

* fixed log stable appearing as kitchen construction

* Reworked to push expansions back to the top level + doc

* testing disallows base name recipe changes

* removal of characters in middle of token managed to offend secret json format mandate

* Adjusted to CleverRaven#46278

* incorporated some old reverse conflict changes

* reorganized the stuff added while this PR was suspended

* reorganized the stuff added while this PR was suspended

* Fix bike shop variant roof

Fix the bike shop variant 1 having an empty roof

* Change stairs to ladder

Changed stairs down to ladder down

* Update the table of contents

* Remove duplicate shortcut keys from interaction menu

Fixes CleverRaven#51772

Co-authored-by: David Seguin <davidseguin@live.ca>

* Jsonified dead scientists map extra

* Use string_id for update_mapgen and nested_mapgen

These ids were previously just using strings; better to use a dedicated
string_id type.

This required adding an actual type for the string_id to point to in
each case, wrapping the collection of mapgen_function_json objects.

* Update cooking_components.json

* Force recipes to provide (sub)category

As suggested in CleverRaven#50866, require all recipe definitions to provide a
category and subcategory when loading from JSON.

* Add subcategory to Magiclysm recipe

* Clarify description of mon_zombie_dog (CleverRaven#51801)

See <https://discord.com/channels/598523535169945603/598614717799596055/890213920957161472> on the dev discord.

* Test disabling expensive LGTM checks (CleverRaven#51806)

Disable one LGTM checks to see if there's hope of reducing the runtime
thereby.

* Mythos Mod Resubmission (CleverRaven#51796)

* Mythos Mod Resubmission

* Remove Occulti as maintainer

* Fix typo in "Storehouse survey" blueprint name

* Add dialog activity functions, and flag to prevent activity being interrupted (CleverRaven#51809)

* Add dialog stuff

* docs

* Update player_activities.json

* use snippets (CleverRaven#51663)

Co-authored-by: Saicchi <Saicchi@users.noreply.github.com>
Co-authored-by: Kevin Granade <kevin.granade@gmail.com>

* Blacksmithing tongs and cooking tongs are two diffrent things.  (CleverRaven#51672)

* Add blacksmithing tongs.

The tongs in game wouldn't be able to carry around a four kilo zweihander. They are designed for cooking and flipping food, so they are very lightweight and thing, they would most likely bend under the heat of the hot metal.

* Added the need to use blacksmithing (flatjaw) tongs for the Zweihander

Not using tongs for smithing is almost impossible.

* Change the blacksmithing toolset to include the tongs.

I also removed the tongs from the tools on the zweihander.

Co-authored-by: Anton Burmistrov <Night_Pryanik@mail.ru>
Co-authored-by: Kevin Granade <kevin.granade@gmail.com>

* More granular json-style and astyle (CleverRaven#51731)

* More granular json-style and astyle

* Melee practice and training dummies (CleverRaven#51598)

* Melee practice
Added some basic melee practice recipes, including 2 for training dodge.
* Training dummy for practice recipes
* Dummy recipe and resolve problems
* Intermediate recipes and heavy training dummy
* Changed the armored dummy recipe
The recipe is inspired by the scrap suit recipe.
* Added tanto as a possible weapon for stabbing training
* Punching bag

Co-authored-by: Marloss <78324429+MarlossCDDA@users.noreply.github.com>

* Write documentation for neighbor based chunk spawning (CleverRaven#51818)

* Resubmit Fix Tire Rims (CleverRaven#51798)

* Update goblin.json (CleverRaven#51799)

* Fix: Force stereo when opening audio device (CleverRaven#51754)

Co-authored-by: Kevin Granade <kevin.granade@gmail.com>

* Add support for weakpoint damage and crit multipliers (CleverRaven#51770)

* Weakpoints (Part 4.5): Add support for JSON inheritance and default weakpoints (CleverRaven#51822)

* Let contributors specify the default weakpoint, by providing an empty ID

* Add support for weakpoint inheritance.

* Reduce debug.log file size by folding consecutive identical errors (CleverRaven#51791)

* debug_fold_repetition: Fold identical errors to reduce log spam

* debug_fold_repetition: added timestamp and timeout

timestamp for repeated error folding group is that of the last folded
error
timeout is currently hardcoded to 100ms. If another repeated error is
registered that would be folded but is >100ms after the previous error
it starts a new folding group

* debug_fold_repetitions: bookended fold for readability, made output DRY

It's a little easier to read the log as `[First]<folded>[Last]` than
`[First]<folded with last timestamp>`
Need to test folding output during deinit and DebugLog, made a function
to remove repetition.

* debug_fold_repetitions: excess repetition error to forced prompt

As logged error the excessive repetition error causes breaks in folds
which make debug.log less clear while reading, and does not add information
Forced prompting once excess threshold is reached will prompt once per
excessive repetition set.

* Allow using any tool with the drilling quality to make a draw_plate (CleverRaven#51794)

Fixes CleverRaven#51688

* The (impotent) Sound and the Fury (CleverRaven#51803)

* update m231

Updated price(https://www.invaluable.com/auction-lot/incredibly-rare-colt-m231-port-firing-u-s-propert-2086-c-3574a02a1e), adjusted desc, set sight disp to that of other no-sight guns, adjusted mod locations.

* Rapidly changing light levels do not grant max vision to turrets (CleverRaven#51815)

* Update fake.json (CleverRaven#51819)

* Fix process effects crash (CleverRaven#51827)

* Add Complete missions dialog function (CleverRaven#51820)

* Complete missions

* Update npctalk.cpp

* Update npctalk.cpp

Co-authored-by: PatrikLundell <j.patrik.r.lundell@gmail.com>
Co-authored-by: SegaSaturnity <75910217+SegaSaturnity@users.noreply.github.com>
Co-authored-by: kevingranade <kevingranade@users.noreply.github.com>
Co-authored-by: UmbralReaper <67179462+UmbralReaper@users.noreply.github.com>
Co-authored-by: David Seguin <davidseguin@live.ca>
Co-authored-by: Valiant <Night_Pryanik@mail.ru>
Co-authored-by: John Bytheway <52664+jbytheway@users.noreply.github.com>
Co-authored-by: mythosmod <91185016+mythosmod@users.noreply.github.com>
Co-authored-by: Kevin Granade <kevin.granade@gmail.com>
Co-authored-by: actual-nh <74678550+actual-nh@users.noreply.github.com>
Co-authored-by: Angela Graves <rivet.the.zombie@gmail.com>
Co-authored-by: Binrui Dong <brett.browning.dong@gmail.com>
Co-authored-by: Eric <52087122+Ramza13@users.noreply.github.com>
Co-authored-by: Saicchi <47158232+Saicchi@users.noreply.github.com>
Co-authored-by: Saicchi <Saicchi@users.noreply.github.com>
Co-authored-by: GOFLUMPYOURSELFPORCAY <64309930+GOFLUMPYOURSELFPORCAY@users.noreply.github.com>
Co-authored-by: Termineitor244 <termineitor244@hotmail.com>
Co-authored-by: Marloss <78324429+MarlossCDDA@users.noreply.github.com>
Co-authored-by: Zhilkin Serg <ZhilkinSerg@users.noreply.github.com>
Co-authored-by: John Candlebury <johncandlebury@gmail.com>
Co-authored-by: The SzQ <37194372+SzQ1@users.noreply.github.com>
Co-authored-by: Joshua Chin <5422226+Joshua-Chin@users.noreply.github.com>
Co-authored-by: OrenAudeles <orenaudeles@gmail.com>
Co-authored-by: Tonkatsu <7764202+tenmillimaster@users.noreply.github.com>
Co-authored-by: Roy Berube <royberube1965@gmail.com>
Co-authored-by: ISuckM8 <87550905+ISuckM8@users.noreply.github.com>
Co-authored-by: ferociousdork <78301810+ferociousdork@users.noreply.github.com>
@OrenAudeles OrenAudeles deleted the debug_fold_repetition branch January 10, 2023 05:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
[C++] Changes (can be) made in C++. Previously named `Code` Code: Debug Debugging and troubleshooting the game, also includes the debug menu
Projects
None yet
Development

Successfully merging this pull request may close these issues.

massive debug log
5 participants