event Handlers not being released

[pludikar]

Hi,

I've been experiencing issues with F360's integration with VSC ever since Spyder was replaced.  I've also been having ongoing PM conversations with @goyals for the last 9 months and I was hopeful that the new debugger release in September would have resolved the issue, but it still lingers.

The issue is that while debugging and frequently after an error is found, particularly with a hierarchy of python modules and more particularly when creating and debugging event handlers, the event handlers do not get deleted as expected when refreshing the code.  I would surmise that something is keeping a reference to handler objects, such that garbage collection doesn't see that the handlers have been released.

When this happens you get multiple calls to the same handler, and it is obvious that older versions of the handler are not removed.  If the handler code is altered (as would happen if you find a bug) it is clear that VSC still has a link to the old handler code version, and single step tracing follows the old code lines.  For example Variables you expect to have corrected values, still behave as if nothing has changed.  Attempts to actively delete or clear previous handlers fail (if reference pointers are still available).  So, in the immediate debugging command line entering 

event.remove(handler) --> results in True

 no matter how many times you execute this.  If the handler was actually removed, it should result in "False" the next time this command is invoked.  This may happen to be a quirk of the VSC/F360 API interface, but it's symptomatic of the underlying issue.

Unfortunately when this this issue arises it is persistent and it's impossible to clear the old handlers, even after breaking the link to the code in VSC, stopping the process under Tools-|Add-ins|Scripts and Add-Ins and then closing down VSC.  Restarting VSC and the debugging session from fresh does not clear the issue - the only way is to shut down and restart F360.

Shyam implied that the F360 team was working on this, but I now guess he's on a different project.  I would consider this to be a significant and major bug and makes working on anything reasonably significant very challenging (I was tempted to use less polite words, but I think you get the point).

I am happy to help and work with you guys/gals, because it's time this was resolved.

Regards

Peter 

[pludikar]

@KrisKaplan 

Kris,

Just in case you are thinking of asking - I disabled my antivirus and a password manager (which did cause other problems with F360 a few years ago, but once I found how to manage it, it hasn't been a problem since).  I haven't done a minimal config diagnostic Windows startup yet - I'll try to do that this evening.

Disabling those 2 apps had no effect on the issue, at least on my machine.

Peter

[pludikar]

@KrisKaplan 

Kris,

Just tried a minimal Windows config yesterday (at least as much as I could, F360 appears to be fussy with the services it needs - all non-Microsoft services and start-up apps were disabled).  The issue behaviour is now very slightly different - and a little worse!:

• I create 11 event handlers every time I start.  This time the handlers were not being removed at all - no dereferenced handler showing up with APIDebug.Eventhandlers.  So after several restarts I was up to 77 referenced Handlers.
• APIDebug.RemoveEventHandlers did nothing to change the result
• Disconnecting and reconnecting VSC and code resulted in unreferenced handlers being listed.

Peter

[pludikar]

@KrisKaplan 

Kris,

Don't mean to overwhelm you with posts, but I just returned my Windows to the normal config, and VSC debugging isn't removing eventHandler references at all now.  Each restart just adds more copies of my code eventhandlers.

It seems to me that there must be a system/VSC/F360 file or memory location that is being created somewhere that isn't being deleted until F360 gets restarted.

Peter

[KrisKaplan]

Peter,

OK. With these steps I was able to see your double events. After some digging through the garbage collector, I am seeing that all the event handlers are being held by a dictionary, and it turned out to be the 'handlers' dictionary in the 'common' module. The problem was that 'common' was not being relatively imported by your 'utils' module. And 'utils' was imported before the relative 'common' in the NesterCommand module. This winds up leaving an absolute 'common' in sys.modules, and that is not deleted as part of the relative module cleanup when we stop the addin. Changing this to a relative import does resolve this. (I believe the reason the attemp to manually clear handlers in the stop method didn't work in this restart case because the module that 'stop' was in was using the relative imported module, but the command handlers were added to the absolute imported module.)

But there is another problem going on with this. The pydev debugger was also holding onto references to the class you had the breakpoint in. This would cause the module, and all the references it was holding (including the handlers array in 'common') when you used restart. The objgraph results of one of these event leaked references is shown below. Basically, there are references to types in a couple of caches in this pydevd_xml module. In an upcoming release, I can add clearing this cache dictionaries in pydevd as part of the 'unload addin' code. (But this wouldn't have fixed the strong references from the absolute imported common module keeping these handlers alive.)

Until this code change gets in, you can manually force detach these caches after stopping your addin with the following:

sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_resolver_cache = {}
sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_str_provider_cache = {}
gc.collect()

FWIW: This is a bit of a whack-a-mole issue are references. The Python debug modules, and Python in general aren't exactly designed with dynamic reload in mind. There's a lot of ways to indirectly leak references to modules that could cause things like this, so it could pay to get comfortable with the garbage collector and tools like objgraph. And keep an eye on what modules your addin adds to sys.modules when it runs (look out for absolute imports that you intended to be relative). But note that if we remove your relative imports from sys.modules on 'stop', it will not guarantee that these modules go unreferenced if there is something else keeping it referenced (in which case, you will just see your types in the garbage collector (gc.get_objects())).

Kris

[pludikar]

@KrisKaplan 

Kris,

I'm relieved that I haven't gone totally bananas😊

Running the three code lines to clear the '_TYPE_RESOLVE_HANDLER'  dicts worked.  Thank you - I wouldn't have found that in a month of sundays, or at least not until I had dived deeply into the depths of Python/F360 internals. 

 The "The problem was that 'common' was not being relatively imported by your 'utils' module" is not implicitly obvious as the import was actually relative in the code ("from .common import *") but, as I understand it, it surreptitiously became absolute because of the order in which it was called.  Am I right?

I think, in summary, it was 50/50 me causing inadvertent and very obscure coding errors and F360/Python/VSC not being totally robust against those errors.  Unfortunately, I was fully expecting to focus on debugging my code and not the underlying environment.  But... I'm really pleased that the bottom has been found (it's been a long while in the making).

I will definitely dig into gc and objgraph, but I would suggest, because F360 is highly sensitive to having relative module references, having an inbuilt tool(s) or command(s) that simply identifies/removes any absolute referenced modules would help anyone in the future who comes across this issue.  Maybe something like LINT would be useful too. Although having these __dict__s emptied on disconnect would be my equal 1st choice.

The biggest things for me was that when this happens, it doesn't become obvious immediately - no error tracebacks, just making code changes that don't actually get incorporated on debug.

IMHO The more robust and bulletproof you can make F360/API/VSC the better it will be for everyone in the future - I am happy to help break and test the environment😁

Anyway, thanks very much for your help - I look forward to seeing your code updates. 

Peter

[pludikar]

Kris,

Just trying to play with gc.get_objects() and after import gc in the debug console I get:

gc.get_objects()
Traceback (most recent call last):
  File "nspylib.zip\automation.py", line 198, in __repr__
  File "nspylib.zip\automation.py", line 459, in _get_value
NotImplementedError: typecode 10 = 0xa)

at first glance, it seems that the public version of F360 doesn't support get_objects.  Am I doing something wrong?

Peter

[pludikar]

Kris,

I figured out what happened with the absolute import - it was actually a double code bug.  The code you got from Github was slightly older than the version I was working on.  I had commented out the code that added the working directory into the sys.path, and at that revealed that I had inadvertently used "from common import *" instead of "from .common import *".  So I had corrected that because Python couldn't find the "common import" in "utils".

Even with the absolute import corrected, I was still getting the multiplying eventhandlers, and I think that was because my system was still polluted with uncollected gc.

I also found that the gc.get_objects() does work, but ONLY if you stop at a breakpoint in the code and in VSC debug terminal.  I get the NotImplementedError when the code is finished and waiting for events and at the Text command line.  Is that what you expect?

I've also put the dict clearing code around the onStop method as a decorator, and that seems to clean things up too.

# Decorator to add debugger dict Clearing
def clearDebuggerDict(method):
    def decoratorWrapper(*args, **kwargs):
        rtn = method(*args, **kwargs)
        sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_resolver_cache = {}
        sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_str_provider_cache = {}
        logger.debug(f'gc.collect count = {gc.collect()}')
        return rtn
    return decoratorWrapper

I tried the code "with" the decorator, then "without" and then "with" again.  The run "without", definitely produced wayward uncollected events, but they cleared when I turned the decorator back on again.

How do you determine using gc and/or objgraph if a module is loaded absolute or relative?

Peter

[pludikar]

Kris,

I figured out what happened with the absolute import - it was actually a double code bug.  The code you got from Github was slightly older than the version I was working on.  I had commented out the code that added the working directory into the sys.path, and at that revealed that I had inadvertently used "from common import *" instead of "from .common import *".  So I had corrected that because Python couldn't find the "common import" in "utils".

Even with the absolute import corrected, I was still getting the multiplying eventhandlers, and I think that was because my system was still polluted with uncollected gc.

I also found that the gc.get_objects() does work, but ONLY if you stop at a breakpoint in the code and in VSC debug terminal.  I get the NotImplementedError when the code is finished and waiting for events and at the Text command line.  Is that what you expect?

I've also put the dict clearing code around the onStop method as a decorator, and that seems to clean things up too.

# Decorator to add debugger dict Clearing
def clearDebuggerDict(method):
    def decoratorWrapper(*args, **kwargs):
        rtn = method(*args, **kwargs)
        sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_resolver_cache = {}
        sys.modules['_pydevd_bundle.pydevd_xml'].__dict__['_TYPE_RESOLVE_HANDLER']._type_to_str_provider_cache = {}
        logger.debug(f'gc.collect count = {gc.collect()}')
        return rtn
    return decoratorWrapper

I tried the code "with" the decorator, then "without" and then "with" again.  The run "without", definitely produced wayward uncollected events, but they cleared when I turned the decorator back on again.

How do you determine using gc and/or objgraph if a module is loaded absolute or relative?  Any guidance would be appreciated.

Peter

[pludikar]

Kris,

It appears that my decorator with your '_TYPE_RESOLVE_HANDLER'  dict clearing workaround generally works, until something happens and it breaks. After that nothing seems to bring it back without restarting F360.  So it's definitely not robust- I suspect there's another area that needs addressing and cleaning up.  If was able to get gc/objgraph to work for me, I would have given you more - but, I'm still trying to figure out the ropes.

FYI: I moved the common and utils modules into a package called "common", and renamed "common" module to "constants".  I also split out the decorator code in "common"  into a module called "decorators".  In the process of figuring what code references I'd missed, I managed to create duplicate eventhandler entries.  Unfortunately the '_TYPE_RESOLVE_HANDLER' method only worked partially - I could see some of the eventhandler references change, but there was an underlying set that would not budge. 

It's highly unlikely that any of my imports were absolute - I've removed the part of the code that extended sys.path, so any import that would have been absolute was flagged as a ModuleNotFound error.  I've uploaded a new version onto Github, if you want to see. 

Peter 

[pludikar]

@KrisKaplan 

Kris,

I just commented out the decorator import on the main nester.py, basically disabling the __dict__ clearing on stop.  Then hit restart several times before actually completing a full run through of the code and avoiding the onStop method (eg putting a breakpoint on line 14 of nestcommand, then restarting at that point).  I now have 77 eventHandlers (ie I ran the restart 7 times) and they won't go away.  I'm 99.9% certain I don't have any absolute imports, because before this test everything consistently cleared back to 11 eventHandlers as expected.

Peter

[KrisKaplan]

Peter,

The absolute reference I was noticing was in utils.py, and NesterCommand.py was importing utils before the relative import of common. I believe this would just result in two instances of the common module being imported, both a relative and absolute one, and the absolute one would not be auto-released by us (because we only release the relative import modules from sys.modules when we stop a script). This would only cause a problem if handlers were put into this absolute import common module's handlers entry.

If you are not running that snippet to release the debugger cache then this is what I mentioned previously would cause the module and any handlers held by it referenced and still active. This manual step will be required until the code change to do this automatically is added. (FWIW: These pydevd* modules and this cache is part of the Microsoft debugpy module, not Fusion360.)

I also noticed that the 'force release of handlers on stop' code is run as part of the script manager. When you click 'restart' in VSCode, this is going underneath the script manager layer (through debugpy) and bypassing this cleanup code. I can log an item to trigger this same cleanup in this scenario. But for now, the simple workaround would be to just avoid using that 'restart' command from VSCode. Instead use the 'stop' and 'run' commands in the 'Scripts and Add-Ins' dialog in Fusion instead.

Kris

[pludikar]

---

The absolute reference I was noticing was in utils.py, and NesterCommand.py was importing utils before the relative import of common. I believe this would just result in two instances of the common module being imported, both a relative and absolute one, and the absolute one would not be auto-released by us (because we only release the relative import modules from sys.modules when we stop a script). This would only cause a problem if handlers were put into this absolute import common module's handlers entry.

Yup - fixed that.

---

If you are not running that snippet to release the debugger cache then this is what I mentioned previously would cause the module and any handlers held by it referenced and still active. This manual step will be required until the code change to do this automatically is added. (FWIW: These pydevd* modules and this cache is part of the Microsoft debugpy module, not Fusion360.)

---

Yup - snippet gets run anytime onStop is reached.  When you keep on top of the wayward eventHandlers it works.

---

I also noticed that the 'force release of handlers on stop' code is run as part of the script manager. When you click 'restart' in VSCode, this is going underneath the script manager layer (through debugpy) and bypassing this cleanup code. I can log an item to trigger this same cleanup in this scenario. But for now, the simple workaround would be to just avoid using that 'restart' command from VSCode. Instead use the 'stop' and 'run' commands in the 'Scripts and Add-Ins' dialog in Fusion instead.

Avoiding restart is an absolute pain (takes multiple clicks in the right order to use stop and run), and frankly, so unfriendly that it defeats whole the  purpose of having an IDE attached to F360.  IMHO Having a good clean IDE environment is absolutely essential and critical to any hope that AD/F360 would have to nurture any outside developers.  Having a good developer ecosystem appears to be a huge ingredient to a product's success - look at Windows and Mac as prime examples.

I look forward to any updates you can come up with in the near future.

Peter 

[pludikar]

Hi Kris,

FWIW: I now have my VSC is the faulty situation. 

• I stopped at a breakpoint at the end of onRun (after my code has been initiated)
• imported gc and objgraph
• did gc.collect()
• then collected all objects into variable - objs = gc.get_objects()
• filtered list to modules -  objs1 = [x for x in gc.get_objects() if type(x) == types.ModuleType]
• filtered obj1 to modules with 'nest' in the name - objs2 = [x for x in objs1 if 'nest' in x.__name__.lower()] 
• and just to make it easier created a similar list with names only - 
  objsname = [x.__name__.split('%2F')[-1] for x in objs1 if 'nest' in x.__name__.lower()]
• looking at this list there were several copies of NesterCommand:
  • 00:'NESTER_py.common'
    01:'NESTER_py.Fusion360CommandBase'
    02:'NESTER_py.NesterCommand'
    03:'NESTER_py.common.constants'
    04:'NESTER_py.common.decorators'
    05:'NESTER_py.common.utils'
    06:'NESTER_py.common'
    07:'NESTER_py.Fusion360CommandBase'
    08:'NESTER_py.NesterCommand'
    09:'NESTER_py.common.constants'
    10:'NESTER_py.common.decorators'
    11:'NESTER_py.common.utils'
    12:'NESTER_py.common'
    13:'NESTER_py.Fusion360CommandBase'
    14:'NESTER_py.NesterCommand'
    15:'NESTER_py.common.constants'
    16:'NESTER_py.common.decorators'
    17:'NESTER_py.common.utils'
    18:'NESTER_py.common'
    19:'NESTER_py.Fusion360CommandBase'
    20:'NESTER_py.NesterCommand'
    21:'NESTER_py.common.constants'
    22:'NESTER_py.common.decorators'
    23:'NESTER_py.common.utils'
    24:'NESTER_py.common'
    25:'NESTER_py.Fusion360CommandBase'
    26:'NESTER_py.NesterCommand'
    27:'NESTER_py.common.constants'
    28:'NESTER_py.common.decorators'
    29:'NESTER_py.common.utils'
    30:'NESTER_py.common'
    31:'NESTER_py.Fusion360CommandBase'
    32:'NESTER_py.NesterCommand'
    33:'NESTER_py.common.constants'
    34:'NESTER_py.common.decorators'
    35:'NESTER_py.common.utils'
    36:'NESTER_py'
    37:'NESTER_py.NesterCommand'
    38:'NESTER_py.common'
    39:'NESTER_py.common.constants'
    40:'NESTER_py.common.decorators'
    41:'NESTER_py.common.utils'
    42:'NESTER_py.Fusion360CommandBase'
• The objgraph (2) of an early version in the list reveals:
• The objgraph (37) of the current (last version) reveals this:
• I don't know if this helps, but it appears that the early version is in a suspended frame (If I interpret that right).  It may be a VSC issue, but unfortunately you are the ones who need to get it fixed, or go to another IDE. 

Peter

[pludikar]

@KrisKaplan 

Kris,

FWIW: I've been trying to abuse VSC over the last few days and it appears that your snippet works pretty well, but it is essential to have it incorporated into the code before any significant code is written or debugging started.

I have found that if the snippet is not present and you restart several times, it will create duplicate eventHandlers which cannot be removed by the snippet (see my previous post for the objgraph).  From what I've seen, the snippet is a prophylactic - it prevents bad things from happening but it is not a cure.  That means, to me at least, that if there happens to be some event or sequence that bypasses the snippet, the issue will appear again.

Peter 

[pludikar]

@KrisKaplan 

Kris,

Just so you know - I was attempting to improve my eventHandler decorator, and in the process caused the irretrievable multiple eventHandler issue. 

Up to that point the snippet was working really well, and I was getting confident. 

Hard to recollect exactly what happened, but I was changing the handler parameters from args to *args, **kwargs, and inadvertently referenced the wrong args.  This resulted in the onStartCreate method that gets decorated to complain.  At this point I noticed that code and debug steps were out of sync, sure enough there were multiple handlers registered.

def eventHandler(handler_cls):
    def decoratorWrapper(notify_method):
        @wraps(notify_method)
        def handlerWrapper(orig_self, *handler_args, **handler_kwargs):

            event = handler_args[0]
            logger.debug(f'notify method created: {notify_method.__name__}')

            try:

                class _Handler(handler_cls):
                    def __init__(self):
                        super().__init__()

                    def notify( self, *args, **kwargs):
                        try:
                            logger.debug(f'{notify_method.__name__} handler notified: {args.firingEvent.name}')
#Changed the following from:
#notify_method(orig_self, args) with appropriate notify(self, args):
#to:
#notify_method(orig_self, *handler_args, **handler_kwargs) by mistake
#then:
#notify_method(orig_self, *args, **kwargs) with appropriate notify(self, *args, **kwargs):

 

                            notify_method(orig_self, *args)#, *args)#, *kwargs)
                        except:
                            logger.exception(f'{args.firingEvent.name} error termination')
                h = _Handler()
                event.add(h)
                handlers.append(Handler(h, event)) #adds to global handlers list
            except:
                logger.exception(f'{handler_cls.name} handler creation error')
            return h
        return handlerWrapper
    return decoratorWrapper

#use example:
@eventHandler(adsk.core.CommandCreatedEventHandler)
    def onStartCreate(self, args:adsk.core.CommandCreatedEventArgs):

        command_ = args.command
        inputs_ = command_.commandInputs
        pass

FYI - I've updated Github 

Peter

[pludikar]

@KrisKaplan 

Kris,

I imagine you've got tired of me, as I've not had a response from you for a couple of weeks😀

The latest version of my code on Github has a flaw that appears to recreate the issue repeatably.

1. load and run/debug my code.
2. verify that 11 event handlers have been created with APIDebug.EventHandlers
3. Click on the Nest button (last button on right on Solid Tab)
   • This will add some badly formed erroneous eventhandlers to the code - you'll see a slew of errors on the Debug Console
4. Click restart
5. You will now have 22 eventHandlers - 11 duplicated shown with APIDebug.EventHandlers - the debugger will not recover from these duplicates.

I hope this helps

Peter

[pludikar]

@KrisKaplan 

Kris,

Just to clarify - the code and process I posted yesterday did not involve either breakpoints or absolute imports.  I removed all breakpoints before restarting F360 from fresh.  This means that the issue is irrecoverably caused by something else - and... it's almost certainly a very simple coding error that anyone could have done (that's one reason for having an IDE).

Peter

[KrisKaplan]

Sorry, I haven't had a chance to debug through your latest code changes yet. Tracking down reference count issues can be time consuming. Using the 'restart' command from VSCode is currently bypassing the 'force release all event handlers' logic. A change to fix this will be in the next release (in January).

Until then, as I mentioned the easy temporary workaround could be to just avoid using 'restart' in VSCode, and always 'stop' the addin from the addins dialog. (Once the script has been stopped from the addin dialog, you can then use 'restart' from VSCode to re-run it if you like, or just hit run from the addin dialog.) I understand that isn't to your liking though.

Kris

[pludikar]

@KrisKaplan 

Kris,

NP.  My only goal and motivation here is to give you enough info, so that your next release (in Jan) is actually worthwhile and meaningful.

I'm pretty confident that the last code version that's presently on Github, has actually uncovered a significant flaw in your VSC integration that probably hasn't been revealed by your findings to date.  Although outwardly similar to the last bug you uncovered, I believe there's enough evidence to suggest this is actually a different beast (I hope I'll be mistaken, but I don't really have a lot of faith at the moment)

I would urge you to test your fix with my broken code before you actually go public in January.  If there's a way you can give me a working preview of the fix, I'd be happy to try and break (err test) it for you.

Peter  

[pludikar]

@KrisKaplan 

Kris,

FWIW: the cause of the last issue appears to be an uncaught exception in the except block of the eventHandler notify creation (ie a double exception - I had the logger trying to log a variable that didn't exist because I had changed the method argument names, and didn't notice those variables further in the code).  A really easy mistake that anyone could have inadvertently stumbled into.  I'm not trying to raise awareness of the coding bug, but more the way VSC/F360 handled it.

I strongly suspect that the exception handling is, if not the root cause, certainly a major cause of this VSC integration issue.

I hope this helps a little

Peter