ryobg / JContainers

JSON-based data structures for Papyrus - the TESV Skyrim SE scripting language
MIT License
107 stars 23 forks source link

More descriptive warning messages #39

Closed RealAntithesis closed 6 years ago

RealAntithesis commented 6 years ago

Currently, if a JC function tries to access a non-existent object, I only get the follow: "Warning: access to non-existing object with id 0x12CA" (or some other object ID).

The problem is that this makes it fairly difficult to pin-point exactly where the issue is in the code (if only Skyrim had some sort of debugger to step through the code...). It would be helpful if the name of the function throwing the warning is also included in the description, as well as providing an integer representation of the object ID (so I don't need to convert it to decimal in the calculator), and the parameters - if that's possible. Thanks

Edit: the method I've been using to date involves commenting out chunks of code until I narrow it down enough to find the problem. It works. I'm just wondering if there was a better way.

ryobg commented 6 years ago

I think JC uses this message only for some functions, for others it silently stops the operation.

Of course, I can add some logging around... I wonder whether for this should be not the user responsible. At the end you pass bad input, so you get bad output... Let me think about it. Especially the function called can be a bit tricky to add.

Why decimal btw?

RealAntithesis commented 6 years ago

Thanks. I suppose my initial concern was that warnings were being printed to the jc log at all. I did narrow down the lines causing the error (by using the aforementioned commenting method) - they were the jmap.getstr() function and the jmap object they were trying to access had been unallocated deliberately, but the variable wasn't zeroed out (usually my custom properties are zeroed out automatically, but this was a temporary variable being used in a debug print function - so not that critical).

My initial reaction was how was I going to find the line causing the warning message since there are literally thousands of objects being accessed over thousands of lines of code, and the warning message gives no detail except for a cryptic object id in hex format (but I figured it out).

While I do keep track of some object id numbers as part of my debugging functions, it doesn't cover all of them - but if it did, it would be in decimal format rather than hex since this is what naturally prints out to my log (as it is, I need to take the hex code and convert in the calculator before it can start making sense to me).

This has given me an idea - maybe I can wrap a function around each new object() to give each object number a string tag (in an intmap) to assist with identification for when the object number pops up in an error message. It will be a fairly large intmap though, but could work.

ryobg commented 6 years ago

I can't advise you how to build your debug system as I do not know your app/code, but I can at least try to improve the facilities with which JC assists in that task. Will improve this and other logged messages too (including #38).

RealAntithesis commented 6 years ago

Great, thanks :)

SilverIce commented 6 years ago

@RealAntithesis in my repo I had a special version which specially caused JC's papyrus function to fail if it accesses deallocated object. In a result, Papyrus log would contain a failed function name and a script name, line number (a user's script line number)

ryobg commented 6 years ago

@SilverIce can you drop some directions where it is? I may get some inspiration.

So far I have decided to log the entry points if you like so. Thus, if it fails you will know which call it was. Though not very useful for multiple users, for debugging sounds nice.

SilverIce commented 6 years ago

A place to throw an exception:

https://github.com/SilverIce/JContainers/blob/diagnostics-v3.3/JContainers/src/collections/bind_traits.h#L25

And this is the place, that catches it:

https://github.com/SilverIce/JContainers/blob/diagnostics-v3.3/dep/skse/skse/PapyrusNativeFunctionDef_Base.inl#L322

Ofc. this is developer-only version

ryobg commented 6 years ago

Is it working? I think it may be added as it is basically.

SilverIce commented 6 years ago

It works, but it's not good solution for general use, since something like JMap.getInt(deleted_object,'key', -1) would probably return 0, not -1

ryobg commented 6 years ago

Oh, yes... you will get logged message and some result which may do. It iwll require some additional logic. Well, for the time being I think just being able to log the API calls may suffice.

ryobg commented 6 years ago

@RealAntithesis I started to add logs when you call an Papyrus API function. You can enable/disable this at runtime. I have added decimal for that other message, but that's it only. I can later share a version with you so for test and feedback. Ok?

ryobg commented 6 years ago

P.S. Ok, there is one build HERE. I haven't tested it as I have no access to my Windows machine, but it should be fine :stuck_out_tongue: Just call enableAPILog with true/false as needed.

RealAntithesis commented 6 years ago

I've tried out enableAPILog() a bit. Unfortunately, this seems to print everything out, regardless of whether there was an error or not and it's difficult to pin point where any issues are (also the output goes beyond the maximum length of the console and everything above this gets lost). Can this output be limited to where it would have printed out an error (such as being given an object that has been unallocated)?

ryobg commented 6 years ago

And I thought this is to be seen in a file, not in the console. I agree it is a bit too detailed, but its use is to turn it on, when you can more or less define where is the problem. Then by looking at this verbose log you can exactly pin-point it. So it is not something to use always.

Note also that there are many problems that can occur outside of your expectations. An example being the bug of improper serialization of string objects. Others, being memory access violations and etc.

Saying that I agree that more effort can be added. Like adding messages for expected problems as you suggested. I will take a look at this and see what it can be done, but... later.

RealAntithesis commented 6 years ago

You're right - it was actually going into the log file - I just didn't think about it. The enableAPILog() was very useful and allowed me to triangulate the line of code. As it turns out, the warning that there was an attempted access to an unallocated object was caused by the JValue.isExists() function. Which seems strange to me, since catching unallocated objects is the exact intent of why isExists() should be used, so it should return true or false to allow the script to determine the next action and not throw a warning or error (since it is warning about something that will be actioned by the script anyway since that's why it was being used in the first place).

ryobg commented 6 years ago

I think in that version, I have mention in the comments that isExist actually checks whether the object is null or not. You may see what argument you have passed to it in the verbose log file. Note however that due to the garbage collection, or maybe some dangling object you still have an reference to, your object may still fail you. I'm not very sure of how useful is this function actually.

RealAntithesis commented 6 years ago

Hmm OK. So it doesn't provide any more debugging information than what I could already get by just checking if an int variable storing the object id is zero or not?

ryobg commented 6 years ago

Yep.

ryobg commented 6 years ago

I'm going to count the enableAPILog for enough support by this time. There is nothing else on my mind that can be done easily and help more. New ideas -> new ticket.