classification
Title: logging.FileHandler not correctly created with PyYaml (unpickling problems?)
Type: crash Stage:
Components: Extension Modules Versions: Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: jordipf, vinay.sajip
Priority: normal Keywords:

Created on 2012-08-10 10:49 by jordipf, last changed 2012-08-30 11:24 by vinay.sajip. This issue is now closed.

Messages (7)
msg167864 - (view) Author: Jordi Puigsegur (jordipf) Date: 2012-08-10 10:49
logging.FileHandler and logging.RotatingFileHandler (haven't tried other handlers) do not get correctly initialized in python 2.7 when loaded using  PyYaml. Therefore I suspect that there is some problem with the implementation of the pickle protocol of these clases in python 2.7.

Attached you can find a small test to reproduce the problem. It works in python 2.5 and 2.6 but fails in python 2.7. In all cases I've used PyYaml 3.10.
msg167865 - (view) Author: Jordi Puigsegur (jordipf) Date: 2012-08-10 10:50
import logging
import logging.handlers
import yaml

logger = logging.getLogger() # root logger

# Option 1 - OK
##handler = logging.handlers.RotatingFileHandler(filename = "test.log", maxBytes = 262144, backupCount = 3)

# Option 2 - RotatingFileHandler fails when created through yaml
handler = yaml.load("""
!!python/object/new:logging.handlers.RotatingFileHandler
    kwds:
        filename: test.log
        maxBytes: 262144
        backupCount: 3
""")

# Option 3 - FileHandler also fails when created through yaml
##handler = yaml.load("""
##!!python/object/new:logging.FileHandler
##    kwds:
##        filename: test.log
##""")

logger.addHandler(handler)

logger.warning("test handler")
msg167880 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-08-10 15:37
The problem appears to be in PyYAML, not logging. Note the content of the attribute dictionaries in the following script:

import logging
import logging.handlers
from pprint import pprint
import yaml

# Option 1 - OK
h1 = logging.handlers.RotatingFileHandler(filename = "test.log", maxBytes = 262144, backupCount = 3)
h2 = yaml.load("""
!!python/object/new:logging.handlers.RotatingFileHandler
    kwds:
        filename: test.log
        maxBytes: 262144
        backupCount: 3
""")
h3 = logging.FileHandler('test.log')
h4 = yaml.load("""
!!python/object/new:logging.FileHandler
    kwds:
        filename: test.log
""")

print('RotatingFileHandler using code: %s' % type(h1))
pprint(h1.__dict__)
print('RotatingFileHandler using YAML: %s' % type(h2))
pprint(h2.__dict__)
print('FileHandler using code: %s' % type(h3))
pprint(h3.__dict__)
print('FileHandler using YAML: %s' % type(h4))
pprint(h4.__dict__)

which prints

RotatingFileHandler using code: <class 'logging.handlers.RotatingFileHandler'>
{'_name': None,
 'backupCount': 3,
 'baseFilename': '/home/vinay/projects/scratch/test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock owner=None count=0>,
 'maxBytes': 262144,
 'mode': 'a',
 'stream': <open file '/home/vinay/projects/scratch/test.log', mode 'a' at 0x1a9f150>}
RotatingFileHandler using YAML: <class 'logging.handlers.RotatingFileHandler'>
{}
FileHandler using code: <class 'logging.FileHandler'>
{'_name': None,
 'baseFilename': '/home/vinay/projects/scratch/test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock owner=None count=0>,
 'mode': 'a',
 'stream': <open file '/home/vinay/projects/scratch/test.log', mode 'a' at 0x1a9f1e0>}
FileHandler using YAML: <class 'logging.FileHandler'>
{}

I suggest that you:

(a) Consider logging an issue with PyYAML.
(b) Consider using dictConfig(), which is available in Python 2.7 amd also available for older Pythons through

http://code.google.com/p/logutils/
msg167885 - (view) Author: Jordi Puigsegur (jordipf) Date: 2012-08-10 16:05
Thanks for your answer.

I am not sure it is a PyYaml bug. Did you notice that the same code works perfectly (with the same version of PyYaml) using python 2.6 and python 2.5? 

Could it be that the issue lies in some change in the way the pickle protocol is implemented in logging classes?
msg167886 - (view) Author: Jordi Puigsegur (jordipf) Date: 2012-08-10 16:08
This is the output of your script when run in python 2.6 and the exact same PyYaml version:

C:\>test.py
RotatingFileHandler using code: <type 'instance'>
{'backupCount': 3,
 'baseFilename': 'C:\\test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock(None, 0)>,
 'maxBytes': 262144,
 'mode': 'a',
 'stream': <open file 'C:\test.log', mode 'a' at 0x00C25BB0>}
RotatingFileHandler using YAML: <type 'instance'>
{'backupCount': 3,
 'baseFilename': 'C:\\test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock(None, 0)>,
 'maxBytes': 262144,
 'mode': 'a',
 'stream': <open file 'C:\test.log', mode 'a' at 0x00C25200>}
FileHandler using code: <type 'instance'>
{'baseFilename': 'C:\\test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock(None, 0)>,
 'mode': 'a',
 'stream': <open file 'C:\test.log', mode 'a' at 0x00C25B10>}
FileHandler using YAML: <type 'instance'>
{'baseFilename': 'C:\\test.log',
 'encoding': None,
 'filters': [],
 'formatter': None,
 'level': 0,
 'lock': <_RLock(None, 0)>,
 'mode': 'a',
 'stream': <open file 'C:\test.log', mode 'a' at 0x00C252A0>}
msg167917 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-08-10 21:33
You've only shown that the YAML loading produces the correct results on 2.6.

Logging changed from old-style classes in 2.6 to new-style classes in 2.7. This may be what is causing PyYAML a problem, but AFAICT PyYAML should work with new-style classes. Perhaps you need to invoke it differently for new-style classes?

Logging doesn't do anything special related to pickling, except that it takes care not to send objects which can't be pickled across the network (which is not relevant here).
msg167958 - (view) Author: Jordi Puigsegur (jordipf) Date: 2012-08-11 14:29
It looks like the change from old to new style classes in python could have triggered this issue.

I've created an issue in PyYaml (http://pyyaml.org/ticket/283). 

Thanks again!
History
Date User Action Args
2012-08-30 11:24:30vinay.sajipsetstatus: pending -> closed
2012-08-11 14:29:05jordipfsetstatus: open -> pending

messages: + msg167958
2012-08-10 21:33:09vinay.sajipsetmessages: + msg167917
2012-08-10 16:08:58jordipfsetmessages: + msg167886
2012-08-10 16:05:25jordipfsetstatus: pending -> open

messages: + msg167885
2012-08-10 15:37:20vinay.sajipsetstatus: open -> pending
assignee: vinay.sajip
resolution: not a bug
messages: + msg167880
2012-08-10 12:18:32r.david.murraysetnosy: + vinay.sajip
2012-08-10 10:50:31jordipfsetmessages: + msg167865
2012-08-10 10:49:17jordipfcreate