This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: EAGAIN errors in Python logging module
Type: Stage: resolved
Components: Extension Modules Versions: Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Henrique Andrade, vinay.sajip, vstinner
Priority: normal Keywords:

Created on 2015-10-22 13:59 by Henrique Andrade, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Messages (6)
msg253329 - (view) Author: Henrique Andrade (Henrique Andrade) Date: 2015-10-22 13:59
There is a particular bug we hit when using the Python logging module very consistently under the particular settings in which we run one of our applications.

We are using Python 2.7.10 on RHEL7/RHEL6/Ubuntu14.04.

Anyways, here is the symptom:

Traceback (most recent call last):
  File "/opt/continuum/anaconda/lib/python2.7/logging/__init__.py", line 880, in emit
    stream.write(fs % msg)
IOError: [Errno 11] Resource temporarily unavailable

Here is the suggested fix:

26c26
< import sys, os, time, cStringIO, traceback, warnings, weakref, collections, errno
---
> import sys, os, time, cStringIO, traceback, warnings, weakref, collections
880,886c880
<                         while True:
< 			    try:
<                                 stream.write(fs % msg)
< 				break
<                             except IOError as e:
<                                 if e.errno != errno.EAGAIN:
< 				   raise
---
>                         stream.write(fs % msg)
msg253330 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-22 14:01
What is the type of the stream? Is is a pipe or a regular file? Or a socket?

Can you please format the patch as an unified patch please?
msg253332 - (view) Author: Henrique Andrade (Henrique Andrade) Date: 2015-10-22 15:03
The stream in this case (where I hit the bug) is just the console, but I
suspect the same issue will affect other streams too.

A key piece of information is that this is probably triggered by having a
custom SIGPIPE handler, which my particular application has.

When a SIGPIPE handler is in place, errors such as EAGAIN and EWOULDBLOCK
might be generated and the logging module wasn't resilient to it.

Here is the unified patch output:

11:00:38|sequoia|/opt/continuum/anaconda> diff -u
/opt/continuum/anaconda/pkgs/python-2.7.8-0/lib/python2.7/logging/__init__.py
/opt/continuum/anaconda/pkgs/python-2.7.8-1/lib/python2.7/logging/__init__.py
---
/opt/continuum/anaconda/pkgs/python-2.7.8-0/lib/python2.7/logging/__init__.py
2014-07-02
19:08:57.000000000 -0400
+++
/opt/continuum/anaconda/pkgs/python-2.7.8-1/lib/python2.7/logging/__init__.py
2015-09-22
13:57:39.196032267 -0400
@@ -23,7 +23,7 @@
 To use, simply 'import logging' and log away!
 """

-import sys, os, time, cStringIO, traceback, warnings, weakref, collections
+import sys, os, time, cStringIO, traceback, warnings, weakref,
collections, errno

 __all__ = ['BASIC_FORMAT', 'BufferingFormatter', 'CRITICAL', 'DEBUG',
'ERROR',
            'FATAL', 'FileHandler', 'Filter', 'Formatter', 'Handler',
'INFO',
@@ -877,7 +877,13 @@
                             #An extra encoding step seems to be needed.
                             stream.write((ufs %
msg).encode(stream.encoding))
                     else:
-                        stream.write(fs % msg)
+                        while True:
+                            try:
+                                stream.write(fs % msg)
+                                break
+                            except IOError as e:
+                                if e.errno != errno.EAGAIN:
+                                    raise
                 except UnicodeError:
                     stream.write(fs % msg.encode("UTF-8"))
             self.flush()

On Thu, Oct 22, 2015 at 10:01 AM, STINNER Victor <report@bugs.python.org>
wrote:

>
> STINNER Victor added the comment:
>
> What is the type of the stream? Is is a pipe or a regular file? Or a
> socket?
>
> Can you please format the patch as an unified patch please?
>
> ----------
> nosy: +haypo
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue25459>
> _______________________________________
>
msg259799 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2016-02-07 18:57
The problem with your suggested fix is that if you keep getting EAGAIN, the handler will appear to hang. If you want to suggest that maybe we limit the number of tries, then what number of retries would you pick, and why? Also, a caller might want to know about EAGAIN, so I'm not sure you'd want to (effectively) swallow it in the handler.

Perhaps a different strategy (than just trying for ever) would be better. If you know the application is unusual in having a SIGPIPE handler and you think this is a contributory factor, why not just subclass the handler, add a more resilient emit() and use that in your application?
msg261373 - (view) Author: Henrique Andrade (Henrique Andrade) Date: 2016-03-08 19:49
Vinay, apologies for the long time you took me to respond (the notification
was stuck in my Spam folder, thanks Gmail!). Indeed, both of your comments
are spot on. In my particular case, I ended up implementing what your first
suggestion alludes to (a retry capped by a maximum).

The reason for my reporting this is because the existing (mainlined)
implementation has shortcomings, which might be affecting others out there.

I contacted the module developer, but no response. So assuming we have a
consensus from whomever "owns" the module, I can volunteer to do a proper
patch.

On the issue of maximum retries, I would go with a reasonable
(configurable) max as well as a (configurable) back-off sleep.

On Sun, Feb 7, 2016 at 1:57 PM, Vinay Sajip <report@bugs.python.org> wrote:

>
> Vinay Sajip added the comment:
>
> The problem with your suggested fix is that if you keep getting EAGAIN,
> the handler will appear to hang. If you want to suggest that maybe we limit
> the number of tries, then what number of retries would you pick, and why?
> Also, a caller might want to know about EAGAIN, so I'm not sure you'd want
> to (effectively) swallow it in the handler.
>
> Perhaps a different strategy (than just trying for ever) would be better.
> If you know the application is unusual in having a SIGPIPE handler and you
> think this is a contributory factor, why not just subclass the handler, add
> a more resilient emit() and use that in your application?
>
> ----------
> status: open -> pending
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue25459>
> _______________________________________
>

-- 

Henrique Andrade | +1-530-426-2123 | hcma@unscrambl.com |
http://unscrambl.com
msg272087 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2016-08-06 10:17
I will close this as not a bug. If you have custom signal handling which interacts with logging in an undesirable way, you will need to subclass the handler. The use case isn't common enough to be addressed in the base handler, IMO.
History
Date User Action Args
2022-04-11 14:58:23adminsetgithub: 69645
2016-08-06 10:17:37vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg272087

stage: resolved
2016-03-08 19:49:22Henrique Andradesetstatus: pending -> open

messages: + msg261373
2016-02-07 18:57:17vinay.sajipsetstatus: open -> pending

messages: + msg259799
2016-02-07 07:17:21ned.deilysetnosy: + vinay.sajip
2015-10-22 15:03:13Henrique Andradesetmessages: + msg253332
2015-10-22 14:01:29vstinnersetnosy: + vstinner
messages: + msg253330
2015-10-22 13:59:55Henrique Andradecreate