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 

[KrisKaplan]

Peter,

I can see from your communications from Shyam that an issue was identified and fixed earlier this year. But obviously that is not the only issue you are dealing with.

There are two ways that event handlers are removed from there events. The first as you mentioned is explicitly calling the 'remove' method on the Event object, passing in the exact same EventHandler reference passed to the 'add' method. The second is when the EventHandler instance goes completely unreferenced and it is garbage collected and destroyed. EventHandler destruction will remove itself from Events that it was attached to.

For the 'Event.remove' method, the contract for this API is that it will return 'True' once it successfully ensures that the specified handler is not attached to the event. This method is idempotent. So yes, calling it with a handler that has already been removed (or was never attached) is not a failure. For a garbage collected language like Python, the most deterministic way to ensure the event handlers are removed from events is to call the remove method.

For the event handler destruction method, this relies on you being able to ensure that all references in your application go unreferenced when your addin stops. If you are careful to only hold references to these handlers in one place (like a 'handlers' global only held by the main module of the addin), this normally wouldn't be a problem. But if you hold references to your handler instances in submodules, or start adding them to the global dictionary of the debug console, then it can easily get out of hand trying to keep track them. Especially because imported modules aren't released from sys.modules by default when referencing modules are unloaded, so any references held by them will not go away either. (A C++ client would typically not have issues like this as destruction order is normally deterministic.)

In production addins aren't (normally) expected to be stopped frequently, so this is mostly a development issue. But The addin samples normally rely on the 'release all references to handlers' method (by just clearing a global 'handlers' list). But if this is not normally a good solution for the way your code is structured or the way you work, I would recommend going with the deterministic 'remove' method. A simple example doing this could look something like the following:

import adsk.core, adsk.fusion, traceback
from typing import Callable, List, NamedTuple
import weakref

app: adsk.core.Application
ui: adsk.core.UserInterface

class Handler(NamedTuple):
    handler: any
    event: weakref.ReferenceType
handlers: List[Handler] = []

def run(context):
    global app, ui
    try:
        app = adsk.core.Application.get()
        ui  = app.userInterface

        event = app.documentActivated
        event.add(createHandler(adsk.core.DocumentEventHandler, onDocumentActivated, event))

        ui.messageBox('Simple Addin Running')

    except:
        if ui:
            ui.messageBox('Failed:\n{}'.format(traceback.format_exc()))

def stop(context):
    global app, ui
    try:
        clearHandlers()

        if ui:
            ui.messageBox('Simple Addin Stopped')

    except:
        if ui:
            ui.messageBox('Failed:\n{}'.format(traceback.format_exc()))
    finally:
        app = None
        ui  = None

def onDocumentActivated(args: adsk.core.DocumentEventArgs):
    ui.messageBox("Document '{}' activated".format(args.document.name))

def defineHandler(handlerType, callback):
    class Handler(handlerType):
        def __init__(self):
            super().__init__()
        def notify(self, args):
            try:
                callback(args)
            except:
                message = 'notify failed: {}'.format(traceback.format_exc())
                if ui:
                    ui.messageBox(message)
                print(message)
    return Handler

def createHandler(handlerType, callback: Callable, event: adsk.core.Event):
    handler = defineHandler(handlerType, callback)()
    handlers.append(Handler(handler, weakref.ref(event)))
    return handler

def clearHandlers():
    global handlers
    for handler in handlers:
        event = handler.event()
        if event:
            event.remove(handler.handler)
    handlers = []

Of course in development, bad things happen. So if you ever stopped/crashed out of your script before releasing all your handlers, you would have lost your references to your handlers so you would have to track down what is referencing them and release those. Typically, this would be from an imported modules. You could look in the 'sys.modules' dictionary in the Fusion python console for your modules (e.g. 'sys.modules.keys()'), and force remove them and trigger a garbage collection (sometimes it takes a few passes for modules). E.g.:

import sys
del sys.modules[mySubModuleKey]
import gc
gc.collect()
gc.collect()

I can also create an issue to force remove all handlers created by a script when that script is stopped. I would think a script should still deterministically handle its callback registrations, but this could act as a (sledgehammer) backstop.

Kris

[pludikar]

 @KrisKaplan 

Hi Kris,

If you have access to Shyam's emails, you'll see that this is an issue that was never really fixed.  It's certainly better than it was, so your fix partially worked.

I totally agree that this is a development cycle issue - for the most part it does behave and eventHandlers do get removed when you activate the VSC restart.  However, because this is in the development cycle, it's inevitable that things/crashes do  happen - otherwise we wouldn't need an IDE platform like VSC.  So I would have expected this to have been resolved as a matter of urgency - I really don't have any problem with a Sledgehammer approach.  In fact I think it's essential, unless you can inherently incorporate it into the VSC integration (which really should be the way to go for the future). 

The fact that completely shutting down and disconnecting the VSC does not force the garbage collection and keeps the event handlers persistent, indicates to me that the sledgehammer should be applied on VSC shutdown (if all else fails throw the on/off switch approach).  It shouldn't be necessary to resort to shutting down F360 as a whole - however I'll try the

import sys
del sys.modules[mySubModuleKey]
import gc
gc.collect()
gc.collect()

approach next time I have same issue (which still happens every once in a while).  I've not figured out what triggers it yet - if I can make it repeatable, I'll let you know.

The code snippet you attached is similar to the approach that I already use, so I'm familiar with that approach.  On debugging restart and object destruction, I actively remove eventHandlers.  Clearly when the code crashes, and restart is applied, the object/event handler destruction code doesn't always get activated, and there's evidently some link/reference to the modules that stops gc from doing it's job. 

Just to re-emphasise - I fully support the request to add a Sledgehammer approach - the quicker it's implemented the better!

Regards

Peter

[pludikar]

@KrisKaplan @goyals 

Hi Kris,

Just to let you know that I modified my code to bring it more into line with the code you suggested.  Essentially just incorporated the NamedTuple and used weakref.ref(event).  I also attempted to use the sys.modules and gc.collect you outlined.  Unfortunately neither resulted in anything useful.

• Immediately onStop the weakref to the event identified itself as 'dead' - so that 

def clearHandlers():
    global handlers
    for handler in handlers:
        event = handler.event()
        if event: #Event always None, so next statement never executed
            event.remove(handler.handler)
    handlers = []​

• Changing Handler(NamedTuple) to:

class Handler(NamedTuple):
    handler: any
    event: any #weakref.ReferenceType
handlers: List[Handler] = []​

 resulted in 

x = event.remove(handler.handler) #x is always True

• I understand that the event.remove call is idempotent, but I would disagree with you that returning True is the right thing to do if the event handler is already removed.  I would argue that either the description associated with remove in the F360 API reference manual (eg here) "Returns true if removal of the handler was successful" is either totally wrong and misleading, Or... (more logically) if the handler isn't there when called, then it isn't successful and should return False
• Forcing gc.collect() did not work as I think you expected.

import sys
del sys.modules[mySubModuleKey]
import gc
gc.collect()
gc.collect()​

 not knowing which specific modules to del. I did the following:

import sys
modules = [x for x in sys.modules.keys() if '__main__' in x]
for module in modules:
   del sys.modules[module]

import gc
gc.collect() #resulted in around 1500 IIRC
gc.collect() #resulted in around 200 IIRC

 maybe the key is not to kill all the __main__ modules, so there should be some guidance here.

• It definitely cleaned up the modules, but... VSC/F360 permanently lost the ability to restart the Add-In (even after stopping the Add-In and clicking Debug in the Add-In dialog - I had to restart F360 from scratch!!  If anything this is worse than just killing and restarting F360, as I suspect this resulted in F360 crashing hard after a few minutes.

Regards

Peter

[KrisKaplan]

FYI: With the release earlier this week, we now force release any event handlers created by an addin that are left connected after stopping the addin. Assuming you can reproduce your issue, give it a try again and let me know how things look.

FWIW: I also added a 'APIDebug.EventHandlers' text command to list connected handlers and the scripts that own them, and 'APIDebug.ReleaseEventHandlers' to release all of the event handlers for a specific addin at any time.

Kris

[pludikar]

@KrisKaplan 

Hi Kris,

Many thanks for the update - I'll let you know how it goes.

Peter

[pludikar]

@KrisKaplan 

Hi Kris,

Something untoward is now going on - I've setup a onCreated Event and this is the sequence of Events that occur after I click on the command button (that is as far as I can tell) - breakpoint in the first line of my eventHandler notify, and each line is a single execution step:

1. CommandStartingHandler in electronicspackagegenerator.py is notified (+ steps to eventArgs.commandID ==)
2. CommandStartingHandler is notified a second time (+ steps to eventArgs.commandID ==)
3. my eventHandler is notifed, but next step immediately jumps to CommandTerminatedHandler
4. CommandTerminatedHandler is notified a second time
5. CommandStartingHandler is notified
6. after that my eventHandler is NOT notified again - and my addIn can't go any further

BTW - how do you expect  'APIDebug.EventHandlers' text command to work.  Both VSC and the F360 Text Command return a 'APIDebug' is not defined

Peter

[KrisKaplan]

It's a little hard to divine what might be going wrong in your handler. Does it run correctly, and just has problems when you are debugging through it? It sounds like perhaps your notify handler threw an exception (which if in the command created event on the definition will terminate the command). And the handler only getting triggered once sounds like either the script is getting stopped, or the event handler was removed. If you can provide a simplified sample with precise steps to reproduce, I can try to debug through it and see what is happening.

From the steps you mentioned, the command started, terminated, and your command created event sequence seems normal. The sequence would normally be:

1. UI start a command (click command button, etc...).

2. Command started event is fired (before starting the sequence of starting the command).

3. Unfortunately, if the command is started from a button click, the started event is fired twice (once by the command click, and one from the command manager). Ideally, one of these should be filtered out to avoid the duplication, but for now you can just ignore this.

4. The api command definition's command created event is fired to create the new command.

5. The current command is ended and the command terminated event is fired.

There is always a command running (normally, when it appears that no command is active the 'select command' is running). So after step 5 above, your command and input events should determine the command lifetime. From the events we talked about so far, if your command terminates or is cancelled for any reason, the sequence starts over at step 2 (starting either the select command or the interrupting command that was started).

So in your sequence below, everything looks normal until you get to your item 5. That 'start' indicates that your command is ending, and a new one is starting. Your command ending could either be that it never started (create command event failed), or all the command inputs are valid (or there were none) and you returned from your execute handler (or didn't have one connected). And not firing again should mean that either the event handler was removed (either explicitely, by dropping all references to it, or by your script module getting unloaded), or the debug session terminated (but you would have noticed that).

APIDebug is a text command. It is available on the 'Text Commands' pallet in the UI (File --> View --> Show Text Commands menu). With the 'Txt' checkbox in the text command window, if you run the 'apidebug' command, it should list the available commands. And if you run 'apidebug.eventhandlers' it will dump a line for every event handler currently attached to an event.

Kris

[pludikar]

@KrisKaplan 

Hi Kris,

Many thanks for responding.  For some reason I assumed that APIDebug was a Python instruction, and I had the Text Command dialog set to Python and not text.  So that's now clear.

It's hard to specifically nail down the cause of the issue because many things changed at the same time: Windows got updated, VSCode python extension was updated and F360 API was also updated all at the same time.  As you may have seen my setup did not like the latest VSCode python extension update.  As a result of all the above it's quite possible that there is some lingering code that's causing some old setting or code to still be active.

I created a decorator to wrap a common eventHandler code around my core command functions: it looks like this:

# Decorator to add eventHandler
def eventHandler(handler_cls, catch_exceptions = True):
    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__}')

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

                def notify( self, args, **kwargs):
                    logger.debug(f'handler notified: {commandEvent.name}')
                    # logger.debug(f'args: {args} {len(args)}')
 
                    if catch_exceptions:
                        try:
                            logger.debug(f'{args}')
                            notify_method(orig_self, args)#, *args)#, *kwargs)
                        except:
                            logger.exception(f'{commandEvent.name} error termination')
                    else:
                        notify_method(orig_self, args)#, *args)# *kwargs)
            h = _Handler()
            event.add(h)
            handlers.append(Handler(h, event)) #adds to global handlers list
            return h
        return handlerWrapper
    return decoratorWrapper

and used like this:

@eventHandler(adsk.core.CommandCreatedEventHandler)
def onCreate(parentCommandObject):
....
....

However, to make sure that the decorator wasn't introducing something to the offending create command I did this:

class OnCreateHandler(adsk.core.CommandCreatedEventHandler):
    def __init__(self):
        super.__init__()
    def notify(self, args):
        eventArgs :adsk.core.CommandEventArgs = args

    # Code to react to the event.
        app = adsk.core.Application.get()
        des :adsk.fusion.Design = app.activeProduct

        self.onCreate(eventArgs)  

This is now failing at the super.__init__(), complaining:

"TypeError: descriptor '__init__' of 'super' object needs an argument". 

I suspect that my decorator needs a try/except block around the class creation.

What is very odd is the VSC python extension breaks in the electronicspackagegenerator.py module before the actual breakpoint in my code.  That's an indicator to me that something has hiccupped.  I'll try cleaning out my VSC folders, and reinstalling VSC, but to all intents and purposes I did that already.

Regards

Peter

[pludikar]

@KrisKaplan 

I figured out the __init__ error - that was my fault 😞 sorry.  it's supposed to be super().__init__(), not super.__init__()

Doesn't resolve the other issue though.

Peter

[pludikar]

@KrisKaplan 

Ok - I found the problem - I probably need to go back to school.  I think it just needed a bit of time off.  I also had to rethink where to put the try/except block, because errors outside that weren't being reported any where, so I was blind.

Peter

[KrisKaplan]

Glad you found it.

Yes. Errors raised during event callbacks can be hard to identify. That's why I would consider wrapping every event handler notification function in a try catch block and make noise (messagebox, breakpoint(), whatever) in debug builds and ideally event logging in a production app when they catch.

Kris

[pludikar]

@KrisKaplan 

Hi Kris,

I've just been working on my addIn and, unfortunately, I don't think we've reached the end of the story with the VSC issues I've been reporting.

The APIDebug.ReleaseEventHandlers Text command, appears to only do a partial job.  If you execute APIDebug.EventHandlers before starting a VSC debug session you get something like this:

APIDebug.EventHandlers 
11 EventHandlers:

DocumentClosing
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

DocumentDeactivating
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

CommandCreated
  ..../AppData/Roaming/Autodesk/ApplicationPlugins/ParameterIO.bundle/Contents/ParameterIO.py

CommandCreated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

DocumentSaving
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

DocumentCreated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

CommandCreated
  ..../AppData/Roaming/Autodesk/ApplicationPlugins/CSV-BOM.bundle/Contents/CSV-BOM.py

CommandCreated
  ..../API/AddIns/dogbone2/dogBone2.py

CommandCreated
  ..../Api/InternalAddins/parts4cad/parts4cad.py

OnCommandTerminated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

OnCommandStarting
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

However, after a session with multiple restarts and after executing an APIDebug.ReleaseEventHandlers I get this:

APIDebug.EventHandlers 
11 EventHandlers:

OnExecute

InputValueChanged

OnDestroy

OnExecutePreview

OnMouseClickEvent

DocumentSaving
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

CommandCreated
  ..../Api/InternalAddins/parts4cad/parts4cad.py

CommandCreated
  ..../AppData/Roaming/Autodesk/ApplicationPlugins/CSV-BOM.bundle/Contents/CSV-BOM.py

DocumentDeactivating
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

CommandCreated
  ..../AppData/Roaming/Autodesk/ApplicationPlugins/ParameterIO.bundle/Contents/ParameterIO.py

DocumentCreated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

DocumentClosing
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

CommandCreated
  ..../AppData/Roaming/Autodesk/Autodesk Fusion 360/API/AddIns/dogbone2/dogBone2.py

CommandCreated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

OnCommandTerminated
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

OnCommandStarting
  ..../Api/InternalAddins/ElectronicsPackageGenerator/ElectronicsPackageGenerator.py

OnDestroy

OnMouseClickEvent

InputValueChanged

OnExecute

OnExecutePreview

OnExecute

InputValueChanged

OnDestroy

OnExecutePreview

OnMouseClickEvent

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

OnDestroy

InputValueChanged

OnExecute

OnMouseClickEvent

OnExecutePreview

CommandCreated

OnExecutePreview

InputValueChanged

OnMouseClickEvent

OnDestroy

CommandCreated

OnExecute

DocumentSaved

CommandCreated

CommandCreated

CommandCreated

DocumentOpened

DocumentActivated

CommandCreated

CommandCreated

DocumentDeactivated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

OnExecute

OnDestroy

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

CommandCreated

OnDestroy

CommandCreated

OnExecute

OnMouseClickEvent

InputValueChanged

OnExecutePreview

You should have noticed that there are numerous blank reference entries.  Normally I wouldn't bring this to your attention, but I am still getting a mis-sync between code in the VSC and what appears to be happening in practice.

For example, after a few debugging restarts (and the inevitable mistooks) - single stepping through the code after a breakpoint results in lines of code being skipped, and clearly the underlying code being debugged is NOT the one that is showing in VSC because exception messages don't correspond to the code that's being highlighted and visible.

I strongly suspect that the blank lines you see in the EventHandlers list above, correspond to old event handlers that have not been fully released and as a result the GC can't clean up.  If that doesn't seem right, then as a minimum the unreferenced eventHandlers should not show up in the APIDebug.EvenHandlers command.

Happy to talk and help out, if you need more.

Peter 

[KrisKaplan]

Peter,

What this debug command is doing is looping over all of the Event objects that are still referenced and alive, and loops over all of the attached event handlers to print out which script owns each handler. The assumption was that normally the only references to Event objects would be from the EventHandlers that are attached to them. But what your output is showing is that there is apparently code that is still holding references to these Event objects after the point that the event handlers have been detached from them (which normally happens when the event handler is destroyed or Event.remove was explicitly called for that handler). I can easily filter out live Event objects that have no event handlers attached to them in a future release.

The code that iterates these event handlers for this output is basically the same that is used to notify these handlers. So this means that any handlers that were attached to these will not be notified if those events are triggered.

I think what you are describing sounds more like the code you are debugging over is just not matching the code that is currently loaded and running (I know, that was the story all along). And the original assumption was that this was due to leaked EventHandler references was the culprit. But it seems fairly apparent from the event handler dump that this is not the actual cause. All of those Event object references are likely coming from your code (assuming that was the only API script activity during your debug session). And those Event references are likely from your module objects, meaning that your modules didn't unload.

Fusion addin/script main entrypoint modules are removed from the system modules dictionary when they are stopped to allow them to reload when re-run. We will also attempt to unload any modules that are loaded relative to the main module. But if you load your script's modules in some other way (like by adding your folder to the sys path and load them absolute), then they will remain referenced by the sys.modules dict and will not reload when you re-run your script. So the first recommendation would be to try to always use relative imports for all of your addin's sub-modules, and only use absolute (sys.path) imports for shared standard modules (which should not change, even during development). If for some reason, you need to use absolute imports for code you want to change during development, then you need to remove those modules from sys.modules explicitly. Perhaps the easiest way to do this would be with importlib.reload.  For example:

import sub1, sub2

if debugging:
    import importlib
    importlib.reload(sub1)
    importlib.reload(sub2)

But take note of some of the details about details in the 'reload' documentation. Otherwise, you could do a manual 'reload' with something like:

import sub1

if debugging:
    # reload
    import sys
    global sub1
    del sub1
    del sys.modules[sub1.__loader__.name]
    import sub1

But going with relative imports would be ideal so it 'just happens'.

Kris

[pludikar]

@KrisKaplan 

Hi Kris,

Many thanks for your detailed response.  To answer some of the things you raised:

• I don't believe I am doing anything unconventional - All my imports are relative, as a rule I don't use absolute because I don't know where the AddIn is going to be located (there are at least two favoured locations in Windows, and one (possibly more) on Mac.)
• "All of those Event object references are likely coming from your code (assuming that was the only API script activity during your debug session)"  - I confirm that there is only one API activity during the debugging session.  The issue is definitely that the code does not unload, at least not without restarting F360!
• If it's any help - you can find the code I'm working on here

"But going with relative imports would be ideal so it 'just happens'" - it certainly used to when I was using Spyder, unfortunately that stopped when you changed to VSC.

Peter

[pludikar]

@KrisKaplan 

Hi Kris,

Just to add to my last post - importlib.reload(mod1) doesn't appear to help.  It's also clear that the module, not only doesn't get unloaded, but the modules appear to just keep getting stacked onto the module list.  I'm using Python's logger and typically when I put a breakpoint in the main module stop(context) function, I can delete the log file that I've created.  I now have a condition where my logger has not only been stopped in the code, but I have manually stopped it too (just in case) - and I cannot delete the file because Windows says that F360 still has it open. This is even after the AddIn has been stopped and disconnected.

Peter 

[pludikar]

@KrisKaplan 

Hi Kris,

To add even more to my last two posts:

I just tried a fresh re-Start of F360, went into my code and launched it in VSC - that does little other than initialize classes and creates some menu panels and buttons.  I then immediately Stopped the code from F360 AddIn dialog, and disconnected VSC.

Executing  APIDebug.Eventhandlers shows that the events I created are orphaned, and clearly the code has not been killed or unloaded by the stop or disconnect.  Waited 10/15 minutes to see if GC would kick in - and nothing changes.

I did have code that added the AddIn path to sys.path, but I removed that before doing the above. 

I can't remember exactly why I added the AddIn path, but I think it was because F360/VSC, at the time, couldn't find modules on the relative path, so that was a work around - though, now it looks like that isn't needed any more.

Peter

[KrisKaplan]

Peter,

I pulled that code and after various rounds of running, stopping, debugging, stepping, detaching, etc... I have not yet seen it leave any of its modules loaded after stopping the addin. I did not notice anything that stood out to me (other than extending sys.path which would normally be a red flag, but that doesn't seem to be used or necessary in this code or any of its imports). If you can easily reproduce this with some simple sequence of steps, let me know and I can try.

As for the logger file handle, I'm not sure what could be holding that open, especially after explicitly closing the FileHandler. Is it possible that there is another addin or script running with a logger using the same name (although releasing it on stop should still kill it)?

You could try looking at the dependency graph of the garbage collector using something like https://mg.pov.lt/objgraph/ once you get into this scenario. But you will likely want to stop every script except yours, and probably also minimize the code to just what's necessary to see this (or the graph could be overwhelming).

Kris

[pludikar]

Kris,

Unfortunately it's really hard to find and document the situation that causes this.  When starting a debug session from fresh there aren't any immediate issues, everything works as expected - then suddenly you realise that things aren't going well and you have to figure out if it's your code (usually is) or something more sinister.  Unfortunately when my mind is focussing on the debugging, I don't have a sixth sense that signals my debug brain when this issue actually starts, so figuring out the sequence of events is really tough.  Sometimes it can be an hour into the debug session before I realise that it's gone awry, sometimes it can be a few sessions.

The logger thing is definitely a symptom, and probably shows that there's an underlying module that didn't get killed when it should have.  Not sure if this is useful but I did noticed that I when I was working on a recursive function, VSC/F360 would not allow a restart until the recursive function had completed in it's entirety - so if there was a bug in the function, it would march on regardless, despite the repeated restart presses.  That's not what I would have expected. 

At the moment I only have the results of the issue to go on - if I could find something that triggered this I think everyone would be happy.  So far the best I have is what I posted last time.

I only work on one addIn code at a time, but I will try your suggestion to look at the GC dependency graph.  I don't have much else running at the same time in F360, but I'll unload anything I do have.  I will also try a clean bare minimum Windows configuration and see if that shows up anything. It wouldn't be the first time I've had conflicts between F360 and my Windows background apps, but I would be surprised if there was anything this time.

BTW - maybe a stupid question - I'm running in a Windows environment, can I assume you are checking on the same environment?

Peter

[pludikar]

@KrisKaplan 

Kris,

I've been struggling to find a suitable way of accessing the python objects that F360 sees, and thus not being able to take advantage of objgraph. 

I've tried finding any related object from both the F360 py command line, VSC debug command line (with and without setting a breakpoint in my code as means of peering into the python F360 objects).  I've also attempted to use gc.get_objects(), but that just returns NotImplemented.  If you could send me some instructions, it would be helpful.  You can send it to me via PM if you'd prefer that. 

However, I think I may have found a repeatable way of creating the issue (or at least something similar), and it's related to VSC restart:

1. using the code I linked to last time, open for debugging
2. place breakpoints on:
   
   1. NESTER.py - line 99 newCommand1.onStop(), prior to full handler unloading and removal
   2. NesterCommand.py - around line 131 __init__, just after the main class initialization
   3. NesterCommand.py - around line 727 onRun method
3. use text command APIDebug.Eventhandlers as a way to track if handlers are orphaned
4. stop all AddIns - to unclutter the result of APIDebug.Eventhandlers
5. APIDebug.Eventhandlers - shows None
6. run the code with breakpoints disabled
7. APIDebug.Eventhandlers - shows 11 fully populated handlers
8. stop and disconnect code
9. APIDebug.Eventhandlers - shows None
10. reactivate code debug, and breakpoints
11. should stop on NestItems class __init__
12. Restart debugging and run through all breakpoints
13. logger shows double entries for each logging instance
14. APIDebug.Eventhandlers - shows 22 fully populated handlers, with 5 unreferenced handlers
15. stop and disconnect code
16. APIDebug.Eventhandlers - shows None
17. Restart debugging and run through all breakpoints
18. Click VSC Restart
19. breakpoint on line 99 (newCommand1.onStop())
20. Click VSC Restart
21. APIDebug.Eventhandlers - shows 22 fully populated handlers, with 15 (up from 5) unreferenced handlers
22. stop and disconnect code
23. APIDebug.Eventhandlers - shows None
24. Restart debugging and run through all breakpoints
25. Click VSC Restart several times in rapid succession
26. run through all breakpoints
27. stop and disconnect code
28. APIDebug.Eventhandlers - shows None
29. do the same for breakpoint line 727 NesterCommand

I suspect event timing may be involved here too - if you hit VSC Restart at any of the breakpoints, before the code is allowed to unload and remove handlers, or reinitialise, then eventually you will probably cause the handlers to become permanent after disconnecting the debugger.  The first time I went through the above sequence, it resulted in the persistent handlers after disconnect, but it didn't the next time - so it may need several goes, but it should get you closer to anything we've had before.

What is concerning, in particular, is the fact that multiple handlers are created, as well as the increasing number of unreferenced handlers - neither is an encouraging sign.  I would suggest that, if you can reproduce this (hopefully you can), then the issue is that the action of VSC Restart doesn't result in Python/F360 memory being totally cleared every time.  I would also suggest Restart should result in a fresh version of code being compiled/interpreted and linked to F360.

I hope this helps move us forward with this problem.

Peter