[BUG] Multiple Python Add-In instances loaded on consecutive stop/start

[Anonymous]

When I stop add-in with `Scripts and Add-Ins` window, and then run it again, actual number of running add-in instances increases by one. So after 3 start/stop cycles I have 3 running add-ins.

You can reproduce this behavior with following add-in:

#Author-Dmytro Kyrychuk
#Description-Test Python add-ins restart

import logging
import logging.handlers
import os.path
import uuid


logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

handler = logging.FileHandler(
    os.path.join(os.path.dirname(__file__), 'log.txt'))
handler.setLevel(logging.DEBUG)

formatter = logging.Formatter('[%(asctime)s] %(message)s')
handler.setFormatter(formatter)

logger.addHandler(handler)


INSTANCE_ID = str(uuid.uuid4())[:8]


logger.debug('{} add-in loaded.'.format(INSTANCE_ID))


def run(context):
    logger.info('{} add-in started.'.format(INSTANCE_ID))


def stop(context):
    logger.info('{} add-in stopped.'.format(INSTANCE_ID))

Log file will contain following after few restart cycles:

[2015-09-07 13:09:11,526] f164d6f8 add-in loaded.
[2015-09-07 13:09:11,527] f164d6f8 add-in started.
[2015-09-07 13:09:16,196] f164d6f8 add-in stopped.
[2015-09-07 13:09:18,486] 41181ed8 add-in loaded.
[2015-09-07 13:09:18,486] 41181ed8 add-in loaded.
[2015-09-07 13:09:18,486] 41181ed8 add-in started.
[2015-09-07 13:09:18,486] 41181ed8 add-in started.
[2015-09-07 13:09:24,201] 41181ed8 add-in stopped.
[2015-09-07 13:09:24,201] 41181ed8 add-in stopped.
[2015-09-07 13:09:25,866] d1bca8b8 add-in loaded.
[2015-09-07 13:09:25,866] d1bca8b8 add-in loaded.
[2015-09-07 13:09:25,866] d1bca8b8 add-in loaded.
[2015-09-07 13:09:25,866] d1bca8b8 add-in started.
[2015-09-07 13:09:25,866] d1bca8b8 add-in started.
[2015-09-07 13:09:25,866] d1bca8b8 add-in started.
[2015-09-07 13:09:31,523] d1bca8b8 add-in stopped.
[2015-09-07 13:09:31,523] d1bca8b8 add-in stopped.
[2015-09-07 13:09:31,523] d1bca8b8 add-in stopped.

Seems like add-in is being correctly reloaded (according to the fact that ID has changed), but for some reason add-in code is being executed multiple times.

Can I expect that developers will see this post here and fix this bug, or I should post it at some another place to achieve that?

[liujac · Accepted solution]

Hi,

The add-in code is not being executed multiple times. Just there are multiple handlers in the logger, so you see duplicated logs in the log file. Please remove the handler from the logger at stop to ensure there is only one handler in your logger at next run.

def stop(context):
    logger.info('{} add-in stopped.'.format(INSTANCE_ID))
    logger.removeHandler(handler)

[Anonymous]

Indeed. Didn't think about that. Thank you!