fix: I/O failures causing a crash + unify logging and assertions

[sleeptightAnsiC]

Hi @adamrehn ,

I reviewed all code related to I/O and made it consistent. Now, whenever we log something, we print it to the stderr with (ue4cli) prefix. Commands that expect to return something still print to stdout. Every exception related to I/O is handled in one place, so now user should not be scared by python callstacks in situations that are perfectly fine. Also found some strange places that were raising default Exception, exiting or printing instead of asserting - I fixed them all.

Tested only on Linux, but I haven't touched anything platform-specific. As always let me know in case something is not right. PR is open for your edits.

EDIT: Also, please see comments below for more info

Cheers!

[TBBle]

I'm uncertain about the overall direction of exception handling here. My initial reaction is that it would be better to wrap exceptions at the point they occur with an UnrealManagerException (carrying the sub-exception using raise from) perhaps, so the top-level handler can expect just that type, and anything that comes through that isn't wrapped is unknown/unexpected. That should be safer (noisier) from library changes introducing exception types we haven't prepared for, and avoids us confusing an expected exception from one source with an unexpected exception from another source in the "one true exception handler" because they share a type.

But that thinking is probably heavily influenced by Go error-handling idiom which uses error-chaining (similar to raise from but you can also match against the cause) heavily; I honestly don't remember if that's the Python idiom or not.

[sleeptightAnsiC]

Hey @TBBle,

I was about to implement this aproach too and even proposed it under your issue. The problem is that after going through every single file and checking every single I/O call, I realized that passing these assertions to UnrealManagerException (or something similar) would spoil the current code way too much and wouldn't really solve the issue. Said exception should only be used for logical issues related to Managers. Everything from Utility class and from file management classes use OS, subprocess and Json modules under the hood so catching these assertions makes the most sense to me right now. KeyboardInterupt is the only case that doesn't fall into these as it derives from ExceptionBase so I had to catch it in this way.

Either way, I'm open for propositions and can change it. I just don't see a better solution for now.

[TBBle]

To me, and again speaking from more-recent Go experience, the advantage of wrapping the exception at the time it enters out domain is that we can add detail about what was going on at the failure time.

For example, with reference to def setEngineRootOverride, it's currently losing all detail on why it thinks that root is invalid. Even with your fix here, you have to look at the chained exception to know what's going on, and that should tell you what went wrong, but from the perspective of the json library, e.g. "Not JSON" versus "File not found" versus "Permission Error". (Also, in this case particularly, your change of a raw Exception which is really a pre-condition check, into an UnrealManagerException in def getEngineVersion, is probably not ideal on reflection: it probably should be a KeyError or ValueError, since we're actually talking about a programming error, not a user-error. Also, looking again, we will also get a KeyError if the JSON file does not have the expected keys, and that may or may not be a user-fixable error.) Anyway, my point here is we don't want to squish all that detail out in favour of "the specified directory does not appear to contain a valid version of the Unreal Engine.", which doesn't actually tell the user what about the directory was not valid.

Another way to do this, rather than wrapping exceptions, is to use add_note to add more details to an exception as it passes by, rather than wrapping it. That might be more-Pythonic, but I actually don't know if that's included in the default stringification, or is normally output by the traceback handler. It is also awkward to use this to distinguish user-fixable input issues from bugs that need to be reported.

Anyway, the end-goal is that the user gets something useful to help identify the issue if it's something they can fix (incorrect input, e.g., pointing setRoot at a non-UE directory), and a stack trace they can post to GitHub if it's a programming error or similar (including pointing setRoot at a directory with a UE version we can't parse due to upstream changes or local corruption), and that our code can (best-effort) tell the difference.

I'm also not fond of dumping stack-traces to users except in clear "unable to handle this unexpected failure" cases, so I'd prefer to have the exception text contain enough info that the user can diagnose it. I suspect in most cases that's fine here, but in some cases (like the def getEngineVersion precondition failure I mentioned above) we should be dumping a stack trace because to resolve that, we need to know what called the failing function, and the parent function definitely needs to not lose that information.

I'd suggest that in the changed code, at Utility.printStderr('(' + type(e).__name__ + ')', str(e)), we also stringify any chained exceptions. That way we aren't losing any detail that has been added with raise from (or simply raise) inside an exception handler.

[sleeptightAnsiC]

I do understand your point @TBBle

I'm wondering how to solve this without creating even bigger mess. Currently, API has pretty much no error handling at all in cases other than UnrealManagerException but I haven't really changed this one. When it comes to the setEngineRootOverride, the "bare" exception was always there, even before my changes, and that would be another issue to solve as I have no idea why it was coded this way. Also, if there are any other naked exceptions in the API, these should be also fixed which isn't really the purpose of this PR.

I'll give it another try today. Maybe it won't take as many changes as I thought. Otherwise, we will have to wait for Adam's response.

[sleeptightAnsiC]

Also, one more note: We were never giving more info about why something failed. The CLI was just crashing when encountering the exception. This was printing the callstack and confusing people a lot. My patch only fixes it for I/O, nothing else. Any other issues will still result in old behavior, but with a message: ue4cli has crashed! Please, report it at .... Fixing this for every call potentially resulting in failure is another topic at all.

[sleeptightAnsiC]

Hey @TBBle ,

Already started implementing everything that you pointed out. Still needs a bit of polishing and testing thought.
I'm glad you reviewed the first commit, as I'm happy with the latest changes. Errors are way clearer right now.
I also entered a new issue about bare exceptions and started looking at possible solutions #67

Would you mind taking a look at PR once again?

For comparison, if user messes with the json files or corrupts them in some way, the patched behavior will look like this:

$ ue4 root
(ue4cli) Error: (UtilityException) failed to load "/home/kornel/.config/ue4cli/config.json" due to: (JSONDecodeError) Expecting value: line 1 column 1 (char 0)
# return code 1

or

$ ue4 root
(ue4cli) Error: (UtilityException) failed to read file "/home/kornel/.config/ue4cli/config.json" due to: (PermissionError) [Errno 13] Permission denied: '/home/kornel/.config/ue4cli/config.json'
# return code 1

Engine crashing looks like this:

$ ue4 run
# logging from Engine...
(ue4cli) Error: (UtilityException) child process ['/home/kornel/UnrealEngine/Engine/Binaries/Linux/UnrealEditor', '/home/kornel/Projects/BlankUnrealProject/BlankUnrealProject.uproject', '-stdout', '-FullStdOutLogOutput'] failed with exit code -11
# return code 1

and sending SIGINT looks like this

$ ue4 run
# logging from Engine...
^C
(ue4cli) Error: (KeyboardInterrupt)
# return code 1

Let me know if this is going in right direction

[sleeptightAnsiC]

This should be now good to merge.

[sleeptightAnsiC]

Whoups... It looks like I merged my personal branch into this PR instead of the other way around.
I already fixed it, but since there are so many commits here, I suggest to squash this PR.

Apologies

[sleeptightAnsiC]

Ofcourse, now whole branch is broken...

[sleeptightAnsiC]

I just did a commit reset and force push. All good again :)