| msg50222 - (view) |
Author: kxroberto (kxroberto) |
Date: 2006-05-09 15:14 |
| The logging package is tagged "beta". Yet cookielib (as the ONLY module in the std. lib !?) uses Logger.debug() very excessively. I got occasional nasty crash traces (from users) when using cookielib Processors through urllib2 (multi-threaded usage) - see below. The causes are not errors in cookielib, but upon simple calls to Logger.debug() : varying AttributeError's in logging, which on the first glance seem to be impossible, as those attributes are set in the related __init__()'s but there are strange complex things going on with roots/hierarchies/copy etc. so.... thread/lock problems I'd guess. the patch uncomments several debug() calls in cookielib in import. only one's in important high-frequency execution flow path (not ones upon errors and exceptional states). And 2 minor fixes on pychecker warnings. After applying that, the nasty crash reports disappeared. I do not understand completely why the cookielib production code has to use the logging package (expensive) at all. At least for the high-frq used add_cookie_header its unnecessary. There could be some simpler (detached) test code for testing purposes. Importing the logging and setup is time consuming etc. (see other patch for urllib2 import optimization. ) I'd recommend: At least as far as logging is "beta" and cookielib NOT, all these debug()'s should be uncommented, or at least called ONLY upon a dispatching global 'use_logging' variable in cookielib, in case the test code cannot be externalized nicely. 2 example error traces: ...File "cookielib.pyo", line 1303, in add_cookie_header\\n\', \' File "logging\\\\__init__.pyo", line 878, in debug\\n\', \' File "logging\\\\__init__.pyo", line 1056, in getEffectiveLevel\\n\', "AttributeError: Logger instance has no attribute \'level\'\\n ...in http_request\\n\', \' File "cookielib.pyo", line 1303, in add_cookie_header\\n\', \' File "logging\\\\__init__.pyo", line 876, in debug\\n\', "AttributeError: Manager instance has no attribute \'disable\'\\n -robert |
|
|
| msg50223 - (view) |
Author: Georg Brandl (georg.brandl) *  |
Date: 2006-05-17 14:46 |
| Logged In: YES user_id=849994 Resolved with rev. 46027 by introducing a global "debug" flag, like other libraries do. |
|
|
| msg50224 - (view) |
Author: Jim Jewett (jimjjewett) |
Date: 2006-05-17 21:34 |
| Logged In: YES user_id=764593 (1) I don't think logging should be removed from the stdlib. At the very least, the reasoning should be added to PEP 337, which says to *add* logging to the standard library. http://www.python.org/dev/peps/pep-0337/ (There will probably be a Summer Of Code student funded to do this; if it is a problem, lets fix the problem in the logging module.) (2) Logging isn't really as unstable as you seem to think Beta implies; it is probably more stable than the newer cookielib, let alone the combination of cookielib, urllib2, and Processors. (John Lee has been making long-overdue fixes to urllib2 -- and processors in particular -- because he was the first to really understand it well enough; these fixes are generally triggered by immediate problems and may not be complete fixes.) I will agree that it might make sense to remove the beta marker from the version of logging that is distributed in the stdlib. (3) What else was shipped with those applications which caused this? Which version of logging did you have? Both tracebacks could be caused if the root logger were not a normal logger (and its manager therefore not a normal manager). Vinay has taken some steps to allow 3rd party libraries to override the class of even the root logger, but doing it *right* is fairly subtle. Another possibility is that you got burned by threads allowing access to half-constructed loggers or managers, or by broken PlaceHolders/fixups in the manager. Again, this can't happen unless someone is doing at least two dangerous things, but ... it has triggered a few of the changelog entries. |
|
|
| msg50225 - (view) |
Author: Georg Brandl (georg.brandl) * |
Date: 2006-05-18 06:21 |
| Logged In: YES user_id=849994 As long as only one standard module uses logging, it's quite useless. And, its use doesn't even comply to PEP 337 ("py." prefix). So if a student wants to implement PEP 337 in SoC, he/she is welcome to do this consistently, and any obscure logging bugs will certainly show up soon after that. |
|
|
| msg50226 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2006-05-18 07:38 |
| Logged In: YES user_id=308438 I've updated the status of the logging package in Subversion from "beta" to "production". This seems reasonable, since the package has been part of Python since 2.3 ;-) I would agree with Jim Jewett that the problems observed are likely to be general threading problems rather than bugs in logging - the latter are unlikely to present with symptoms such as those described. |
|
|
| msg50227 - (view) |
Author: John J Lee (jjlee) |
Date: 2007-01-31 22:38 |
| Just adding some notes for the record since I didn't spot this patch at the time 1. Deadlocks Deadlocks when using threads with cookielib were almost *expected*, because of cookielib and not because of module logging (at least before the try/finally suites were added by a different patch from kxroberto recently -- perhaps that patch fixes the threading problems). To my embarassment, the thread locks in cookielib got into the Python 2.4 release pretty much by accident when I got sick shortly before the first beta (search for "untested" in the first link...): http://mail.python.org/pipermail/python-dev/2004-May/044785.html http://mail.python.org/pipermail/python-list/2005-January/304651.html After the release, I suggested that all thread synchronisation be removed (they are not present in non-stdlib modules ClientCookie/mechanize, which share a common ancestor with cookielib, and that certainly does not rule out threaded use), since threaded use was surely thoroughly broken -- or at least add a prominent warning in the docs about the thread-broken-ness. The opinion was that the thread synchronisation should instead be fixed (fair enough), so the locks were left in and the warning was not added. I didn't supply the obvious patch to add try/finally blocks, since it's not obvious to me that that is sufficient (I don't mean to say here that it's not sufficient -- I'm just not sure). 2. Why logging? gbrandl: "As long as only one standard module uses logging, it's quite useless." The logging in cookielib has a concrete, practical purpose, Writing web client code very frequently involves working out why your code does not precisely imitate a web browser; this unavoidably happens more often than with other protocols, because web browsers are very complicated, so no web client library implements all browser features (let alone correctly). If you think cookies should get returned to the server, and they don't, turning on logging immediately tells you why. This results in a big time saving over debugging the code every tims this happens. There is indeed an *additional* benefit to be had by many modules all using module logging. That was often proposed at the time, so it seemed sensible to use module logging rather than print statements. It seems that the people who suggested that have not implemented it. Still, given the actual need for logging in this case, the alternative was to invent something else that does a similar job. httplib does exactly that (it predates module logging), using simple print statements and a flag to turn them on. OTOH, I have already heard complaints that httplib should be using module logging instead, because that is convenient when using non-stdlib code that uses module logging. Re performance: has anybody actually *measured* a significant (that is, problematic) performance impact caused by *this particular* module's use of module logging? If so, a performance hack could be added to cookielib. |
|
|