{"action":"created","issue":{"url":"https://api.github.com/repos/jacquev6/ActionTree/issues/6","repository_url":"https://api.github.com/repos/jacquev6/ActionTree","labels_url":"https://api.github.com/repos/jacquev6/ActionTree/issues/6/labels{/name}","comments_url":"https://api.github.com/repos/jacquev6/ActionTree/issues/6/comments","events_url":"https://api.github.com/repos/jacquev6/ActionTree/issues/6/events","html_url":"https://github.com/jacquev6/ActionTree/issues/6","id":293817421,"number":6,"title":"Occasional hangs when using multiprocessing_logging","user":{"login":"ntnn","id":10514301,"avatar_url":"https://avatars3.githubusercontent.com/u/10514301?v=4","gravatar_id":"","url":"https://api.github.com/users/ntnn","html_url":"https://github.com/ntnn","followers_url":"https://api.github.com/users/ntnn/followers","following_url":"https://api.github.com/users/ntnn/following{/other_user}","gists_url":"https://api.github.com/users/ntnn/gists{/gist_id}","starred_url":"https://api.github.com/users/ntnn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ntnn/subscriptions","organizations_url":"https://api.github.com/users/ntnn/orgs","repos_url":"https://api.github.com/users/ntnn/repos","events_url":"https://api.github.com/users/ntnn/events{/privacy}","received_events_url":"https://api.github.com/users/ntnn/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2018-02-02T09:02:10Z","updated_at":"2018-02-22T09:02:58Z","closed_at":"2018-02-22T09:02:58Z","author_association":"CONTRIBUTOR","body":"I'm experiencing occasional lockups when using logging with the multiprocessing_logging module (or any other library trying to accomplish similar things).\r\n\r\nThe started subprocesses do finish, but occasionally hang indefinitely on a futex call.\r\n\r\nMinimal example:\r\n```python\r\nimport logging\r\nlogging.basicConfig(level=logging.DEBUG)\r\nimport multiprocessing_logging as mpl\r\nmpl.install_mp_handler()\r\nlog = logging.getLogger(__name__)\r\n\r\nimport ActionTree\r\n\r\n\r\nclass DoSomething(ActionTree.Action):\r\n    def __init__(self, cmd, *args, **kwargs):\r\n        self.cmd = cmd\r\n        self.args = args\r\n        ActionTree.Action.__init__(self, ' '.join(self.cmdline), **kwargs)\r\n        log.debug('Created Action with label %s: %s %r', self.label, cmd, args)\r\n\r\n    @property\r\n    def cmdline(self):\r\n        x = [self.cmd]\r\n        x.extend(self.args)\r\n        return x\r\n\r\n    def do_execute(self, dependency_statuses):\r\n        log.info('Executing cmd %s', self.cmd)\r\n        from subprocess import Popen\r\n        proc = Popen(self.cmdline)\r\n        proc.wait()\r\n        log.debug('Cmd %s exitcode: %d', self.cmd, proc.returncode)\r\n\r\n\r\nhello_world = DoSomething('echo', 'Hello, World!')\r\ndownload_webpage = DoSomething('curl', '-o', 'index.html', 'https://nelo.wallus.de/')\r\ntouch_file = DoSomething('touch', 'example-file')\r\n\r\ndownload_webpage.add_dependency(hello_world)\r\ntouch_file.add_dependency(download_webpage)\r\n\r\nActionTree.execute(touch_file)\r\n```\r\n\r\nI'm retrieving the PID of the subprocesses started by ActionTree by printing them in __init__.py#L905. Stracing that yield the futex class:\r\n```\r\nfutex(..., FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ...\r\n```\r\n\r\nBy adding multiple prints to `_run_action` I could verify that the action is indeed finishing up, the process itself just hangs on the futex.\r\n\r\nOne possibility was python's fork-lock bug (stdlib locks being forked in locked state an then never released): https://bugs.python.org/issue6721\r\n\r\nHowever even just writing the messages to a multiprocessing.Queue starts to lock the subprocess on a futex:\r\n\r\n```python\r\nimport logging\r\nlogging.basicConfig(level=logging.DEBUG)\r\nlogger = logging.getLogger(__name__)\r\n\r\nimport ActionTree\r\n\r\nfrom multiprocessing import Queue\r\n\r\n\r\nclass MyLogger():\r\n    queue = Queue()\r\n    thread = None\r\n    closed = False\r\n\r\n    @classmethod\r\n    def put(cls, level, msg, *args, **kwargs):\r\n        cls.queue.put({'level': level, 'msg': msg, 'args': args, 'kwargs': kwargs})\r\n\r\n    @classmethod\r\n    def start(cls):\r\n        if cls.thread:\r\n            return\r\n        import threading\r\n        cls.thread = threading.Thread(target=cls.run)\r\n        cls.thread.daemon = True\r\n        cls.thread.start()\r\n\r\n    @classmethod\r\n    def run(cls):\r\n        import queue\r\n        while not (cls.closed and cls.queue.empty()):\r\n            try:\r\n                d = cls.queue.get(1, True)\r\n                logger._log(d['level'], d['msg'], *d['args'], **d['kwargs'])\r\n            except EOFError:\r\n                break\r\n            except queue.Empty:\r\n                continue\r\n        cls.queue.close()\r\n        cls.queue.join_thread()\r\n\r\n    @classmethod\r\n    def stop(cls):\r\n        if cls.thread and not cls.closed:\r\n            cls.closed = True\r\n            cls.thread.join()\r\n            cls.thread.join()\r\n\r\n\r\nMyLogger.start()\r\n\r\n\r\nclass log():\r\n    @staticmethod\r\n    def log(level, msg, *args, **kwargs):\r\n        MyLogger.put(level, msg, args, kwargs)\r\n\r\n    @classmethod\r\n    def debug(cls, msg, *args, **kwargs):\r\n        cls.log(logging.DEBUG, msg, *args, **kwargs)\r\n\r\n    @classmethod\r\n    def info(cls, msg, *args, **kwargs):\r\n        cls.log(logging.INFO, msg, *args, **kwargs)\r\n\r\n    @classmethod\r\n    def warning(cls, msg, *args, **kwargs):\r\n        cls.log(logging.WARNING, msg, *args, **kwargs)\r\n\r\n    @classmethod\r\n    def error(cls, msg, *args, **kwargs):\r\n        cls.log(logging.ERROR, msg, *args, **kwargs)\r\n\r\n    @classmethod\r\n    def critical(cls, msg, *args, **kwargs):\r\n        cls.log(logging.critical, msg, *args, **kwargs)\r\n\r\n\r\nclass DoSomething(ActionTree.Action):\r\n    def __init__(self, cmd, *args, **kwargs):\r\n        self.cmd = cmd\r\n        self.args = args\r\n        ActionTree.Action.__init__(self, ' '.join(self.cmdline), **kwargs)\r\n        log.debug('Created Action with label %s: %s %r', self.label, cmd, args)\r\n\r\n    @property\r\n    def cmdline(self):\r\n        x = [self.cmd]\r\n        x.extend(self.args)\r\n        return x\r\n\r\n    def do_execute(self, dependency_statuses):\r\n        # log.info('Executing cmd %s', self.cmd)\r\n        from subprocess import Popen\r\n        proc = Popen(self.cmdline)\r\n        proc.wait()\r\n        # log.debug('Cmd %s exitcode: %d', self.cmd, proc.returncode)\r\n\r\n\r\nhello_world = DoSomething('echo', 'Hello, World!')\r\ndownload_webpage = DoSomething('curl', '-o', 'index.html', 'https://nelo.wallus.de/')\r\ntouch_file = DoSomething('touch', 'example-file')\r\n\r\ndownload_webpage.add_dependency(hello_world)\r\ntouch_file.add_dependency(download_webpage)\r\n\r\nActionTree.execute(touch_file)\r\n\r\nMyLogger.stop()\r\n```\r\n\r\nCommenting out the log.* calls still causes a deadlock with a futex call.\r\n\r\nI'm currently out of ideas. I'll see if I can get anything useful looking at the issue with gdb later on."},"comment":{"url":"https://api.github.com/repos/jacquev6/ActionTree/issues/comments/367612154","html_url":"https://github.com/jacquev6/ActionTree/issues/6#issuecomment-367612154","issue_url":"https://api.github.com/repos/jacquev6/ActionTree/issues/6","id":367612154,"user":{"login":"jacquev6","id":327146,"avatar_url":"https://avatars1.githubusercontent.com/u/327146?v=4","gravatar_id":"","url":"https://api.github.com/users/jacquev6","html_url":"https://github.com/jacquev6","followers_url":"https://api.github.com/users/jacquev6/followers","following_url":"https://api.github.com/users/jacquev6/following{/other_user}","gists_url":"https://api.github.com/users/jacquev6/gists{/gist_id}","starred_url":"https://api.github.com/users/jacquev6/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jacquev6/subscriptions","organizations_url":"https://api.github.com/users/jacquev6/orgs","repos_url":"https://api.github.com/users/jacquev6/repos","events_url":"https://api.github.com/users/jacquev6/events{/privacy}","received_events_url":"https://api.github.com/users/jacquev6/received_events","type":"User","site_admin":false},"created_at":"2018-02-22T09:02:58Z","updated_at":"2018-02-22T09:02:58Z","author_association":"OWNER","body":"@ntnn I'm closing this issue because I don't think the problem is in ActionTree, as explained above. Don't hesitate to reopen if you have new insights."}}
{"actor":{"display_login":"jacquev6"}}