[Patches] [ python-Patches-1484758 ] cookielib: reduce (fatal) dependency on "beta" logging?

[SourceForge.net]

Patches item #1484758, was opened at 2006-05-09 16:14
Message generated for change (Comment added) made by jjlee
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=305470&aid=1484758&group_id=5470

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Library (Lib)
Group: Python 2.4
Status: Closed
Resolution: Fixed
Priority: 5
Private: No
Submitted By: kxroberto (kxroberto)
Assigned to: Nobody/Anonymous (nobody)
Summary: cookielib: reduce (fatal) dependency on "beta" logging?

Initial Comment:
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

----------------------------------------------------------------------

Comment By: John J Lee (jjlee)
Date: 2007-01-31 22:38

Message:
Logged In: YES 
user_id=261020
Originator: NO

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.


----------------------------------------------------------------------

Comment By: Vinay Sajip (vsajip)
Date: 2006-05-18 08:38

Message:
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.

----------------------------------------------------------------------

Comment By: Georg Brandl (gbrandl)
Date: 2006-05-18 07:21

Message:
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.

----------------------------------------------------------------------

Comment By: Jim Jewett (jimjjewett)
Date: 2006-05-17 22:34

Message:
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.




----------------------------------------------------------------------

Comment By: Georg Brandl (gbrandl)
Date: 2006-05-17 15:46

Message:
Logged In: YES 
user_id=849994

Resolved with rev. 46027 by introducing a global "debug"
flag, like other libraries do.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=305470&aid=1484758&group_id=5470