Can I log with thread names/IDs in `__del__` methods?











up vote
1
down vote

favorite












In the Python stdlib's logging library, using the %(thread) or %(threadName) macro (documented here) calls threading.current_thread (code), which takes out a threading-internal lock.



This, as per the warnings in the __del__ documentation, causes a problem if you want to log inside __del__. We've run into a single-threaded deadlocking issue caused by this.



So, my question: is there an always-safe way to log from inside __del__ methods? It'd be nice to log information about, in our case, connections being closed as the result of their owners being GC'd, but this can cause problems in the (perhaps unlikely) case that a user turns on debug logging and adds threading information to their debug configuration. I have found some posts about more explicit resource-sharing in __del__, but none about the stdlib logging behavior.










share|improve this question






















  • What about just storing the thread name as an instance variable when you start the thread?
    – larsks
    Nov 9 at 16:08






  • 1




    @larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
    – user2357112
    Nov 9 at 16:10










  • Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
    – user2357112
    Nov 9 at 16:20










  • What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
    – Jim Witschey
    Nov 9 at 16:29















up vote
1
down vote

favorite












In the Python stdlib's logging library, using the %(thread) or %(threadName) macro (documented here) calls threading.current_thread (code), which takes out a threading-internal lock.



This, as per the warnings in the __del__ documentation, causes a problem if you want to log inside __del__. We've run into a single-threaded deadlocking issue caused by this.



So, my question: is there an always-safe way to log from inside __del__ methods? It'd be nice to log information about, in our case, connections being closed as the result of their owners being GC'd, but this can cause problems in the (perhaps unlikely) case that a user turns on debug logging and adds threading information to their debug configuration. I have found some posts about more explicit resource-sharing in __del__, but none about the stdlib logging behavior.










share|improve this question






















  • What about just storing the thread name as an instance variable when you start the thread?
    – larsks
    Nov 9 at 16:08






  • 1




    @larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
    – user2357112
    Nov 9 at 16:10










  • Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
    – user2357112
    Nov 9 at 16:20










  • What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
    – Jim Witschey
    Nov 9 at 16:29













up vote
1
down vote

favorite









up vote
1
down vote

favorite











In the Python stdlib's logging library, using the %(thread) or %(threadName) macro (documented here) calls threading.current_thread (code), which takes out a threading-internal lock.



This, as per the warnings in the __del__ documentation, causes a problem if you want to log inside __del__. We've run into a single-threaded deadlocking issue caused by this.



So, my question: is there an always-safe way to log from inside __del__ methods? It'd be nice to log information about, in our case, connections being closed as the result of their owners being GC'd, but this can cause problems in the (perhaps unlikely) case that a user turns on debug logging and adds threading information to their debug configuration. I have found some posts about more explicit resource-sharing in __del__, but none about the stdlib logging behavior.










share|improve this question













In the Python stdlib's logging library, using the %(thread) or %(threadName) macro (documented here) calls threading.current_thread (code), which takes out a threading-internal lock.



This, as per the warnings in the __del__ documentation, causes a problem if you want to log inside __del__. We've run into a single-threaded deadlocking issue caused by this.



So, my question: is there an always-safe way to log from inside __del__ methods? It'd be nice to log information about, in our case, connections being closed as the result of their owners being GC'd, but this can cause problems in the (perhaps unlikely) case that a user turns on debug logging and adds threading information to their debug configuration. I have found some posts about more explicit resource-sharing in __del__, but none about the stdlib logging behavior.







python logging del






share|improve this question













share|improve this question











share|improve this question




share|improve this question










asked Nov 9 at 16:04









Jim Witschey

142112




142112












  • What about just storing the thread name as an instance variable when you start the thread?
    – larsks
    Nov 9 at 16:08






  • 1




    @larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
    – user2357112
    Nov 9 at 16:10










  • Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
    – user2357112
    Nov 9 at 16:20










  • What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
    – Jim Witschey
    Nov 9 at 16:29


















  • What about just storing the thread name as an instance variable when you start the thread?
    – larsks
    Nov 9 at 16:08






  • 1




    @larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
    – user2357112
    Nov 9 at 16:10










  • Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
    – user2357112
    Nov 9 at 16:20










  • What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
    – Jim Witschey
    Nov 9 at 16:29
















What about just storing the thread name as an instance variable when you start the thread?
– larsks
Nov 9 at 16:08




What about just storing the thread name as an instance variable when you start the thread?
– larsks
Nov 9 at 16:08




1




1




@larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
– user2357112
Nov 9 at 16:10




@larsks: You still wouldn't know which thread the logging call is executing on. You'd need to call threading.current_thread(), which would produce the same deadlock.
– user2357112
Nov 9 at 16:10












Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
– user2357112
Nov 9 at 16:20




Incidentally, there's a proposal for a mode where the GC runs on its own thread, which would make some of these problems easier. I'm not sure if that proposal is going anywhere, though.
– user2357112
Nov 9 at 16:20












What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
– Jim Witschey
Nov 9 at 16:29




What about just storing the thread name as an instance variable when you start the thread? -- in our case that's not worth the overhead of adding that instance variable to every single debug call. And, as @user2357112 mentioned, this wouldn't solve the issue anyway.
– Jim Witschey
Nov 9 at 16:29












1 Answer
1






active

oldest

votes

















up vote
2
down vote



accepted










The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.



The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.



Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like



import queue
del_log_queue = queue.SimpleQueue()

def stop_del_logging():
del_log_queue.put(None)

...

def __del__(self):
del_log_queue.put((tuple, of, relevant, information))

...

# in some other thread

while True:
info = del_log_queue.get()
if info is None:
break
relevant_logger.log(do_something_with(info))


In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.






share|improve this answer























    Your Answer






    StackExchange.ifUsing("editor", function () {
    StackExchange.using("externalEditor", function () {
    StackExchange.using("snippets", function () {
    StackExchange.snippets.init();
    });
    });
    }, "code-snippets");

    StackExchange.ready(function() {
    var channelOptions = {
    tags: "".split(" "),
    id: "1"
    };
    initTagRenderer("".split(" "), "".split(" "), channelOptions);

    StackExchange.using("externalEditor", function() {
    // Have to fire editor after snippets, if snippets enabled
    if (StackExchange.settings.snippets.snippetsEnabled) {
    StackExchange.using("snippets", function() {
    createEditor();
    });
    }
    else {
    createEditor();
    }
    });

    function createEditor() {
    StackExchange.prepareEditor({
    heartbeatType: 'answer',
    convertImagesToLinks: true,
    noModals: true,
    showLowRepImageUploadWarning: true,
    reputationToPostImages: 10,
    bindNavPrevention: true,
    postfix: "",
    imageUploader: {
    brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
    contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
    allowUrls: true
    },
    onDemand: true,
    discardSelector: ".discard-answer"
    ,immediatelyShowMarkdownHelp:true
    });


    }
    });














    draft saved

    draft discarded


















    StackExchange.ready(
    function () {
    StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f53229289%2fcan-i-log-with-thread-names-ids-in-del-methods%23new-answer', 'question_page');
    }
    );

    Post as a guest















    Required, but never shown

























    1 Answer
    1






    active

    oldest

    votes








    1 Answer
    1






    active

    oldest

    votes









    active

    oldest

    votes






    active

    oldest

    votes








    up vote
    2
    down vote



    accepted










    The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.



    The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.



    Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like



    import queue
    del_log_queue = queue.SimpleQueue()

    def stop_del_logging():
    del_log_queue.put(None)

    ...

    def __del__(self):
    del_log_queue.put((tuple, of, relevant, information))

    ...

    # in some other thread

    while True:
    info = del_log_queue.get()
    if info is None:
    break
    relevant_logger.log(do_something_with(info))


    In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.






    share|improve this answer



























      up vote
      2
      down vote



      accepted










      The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.



      The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.



      Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like



      import queue
      del_log_queue = queue.SimpleQueue()

      def stop_del_logging():
      del_log_queue.put(None)

      ...

      def __del__(self):
      del_log_queue.put((tuple, of, relevant, information))

      ...

      # in some other thread

      while True:
      info = del_log_queue.get()
      if info is None:
      break
      relevant_logger.log(do_something_with(info))


      In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.






      share|improve this answer

























        up vote
        2
        down vote



        accepted







        up vote
        2
        down vote



        accepted






        The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.



        The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.



        Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like



        import queue
        del_log_queue = queue.SimpleQueue()

        def stop_del_logging():
        del_log_queue.put(None)

        ...

        def __del__(self):
        del_log_queue.put((tuple, of, relevant, information))

        ...

        # in some other thread

        while True:
        info = del_log_queue.get()
        if info is None:
        break
        relevant_logger.log(do_something_with(info))


        In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.






        share|improve this answer














        The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.



        The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.



        Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like



        import queue
        del_log_queue = queue.SimpleQueue()

        def stop_del_logging():
        del_log_queue.put(None)

        ...

        def __del__(self):
        del_log_queue.put((tuple, of, relevant, information))

        ...

        # in some other thread

        while True:
        info = del_log_queue.get()
        if info is None:
        break
        relevant_logger.log(do_something_with(info))


        In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.







        share|improve this answer














        share|improve this answer



        share|improve this answer








        edited Nov 22 at 6:33

























        answered Nov 9 at 16:36









        user2357112

        149k12155243




        149k12155243






























            draft saved

            draft discarded




















































            Thanks for contributing an answer to Stack Overflow!


            • Please be sure to answer the question. Provide details and share your research!

            But avoid



            • Asking for help, clarification, or responding to other answers.

            • Making statements based on opinion; back them up with references or personal experience.


            To learn more, see our tips on writing great answers.





            Some of your past answers have not been well-received, and you're in danger of being blocked from answering.


            Please pay close attention to the following guidance:


            • Please be sure to answer the question. Provide details and share your research!

            But avoid



            • Asking for help, clarification, or responding to other answers.

            • Making statements based on opinion; back them up with references or personal experience.


            To learn more, see our tips on writing great answers.




            draft saved


            draft discarded














            StackExchange.ready(
            function () {
            StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fstackoverflow.com%2fquestions%2f53229289%2fcan-i-log-with-thread-names-ids-in-del-methods%23new-answer', 'question_page');
            }
            );

            Post as a guest















            Required, but never shown





















































            Required, but never shown














            Required, but never shown












            Required, but never shown







            Required, but never shown

































            Required, but never shown














            Required, but never shown












            Required, but never shown







            Required, but never shown







            這個網誌中的熱門文章

            Tangent Lines Diagram Along Smooth Curve

            Yusuf al-Mu'taman ibn Hud

            Zucchini