[Twisted-Python] supressess warnings
I'm just starting to learn how to use Twisted. My first project is to write a simple XML-RPC server. I started with the demo, and that worked fine. I then added an import statement for the module I need. from openeye.oechem import * Now, this uses a shared library extension which was built for Python 2.2, and I'm running a CVS version of Python 2.3, so I usually get /usr/local/lib/python2.3/site-packages/openeye/oechem.py:5: RuntimeWarning: Python C API version mismatch for module _oechem: This Python has API version 1012, module _oechem has version 1011. import _oechem However, that didn't happen when I started my my simple server. I got no warning message. I started to worry that my file system wasn't properly saving files! I played around with the imports, and moved that import to be above the twisted ones, and it started reporting the warning. A bit of searching later and I found twisted/python/log.py which redefines (!) warnings.showwarning to dump the data to a logfile, which is initialized to a NullFile(), which does nothing. So the twisted code is throwing some (potentially useful) diagnostics. Doing a search I found the commit statement http://twistedmatrix.com/pipermail/twisted-commits/2002-October/ 003975.html
I'll grant that's what the docs say. However, why is the logfile for showwarnings initialized to NullFile, and not to sys.stderr? For that matter, I think it's better to delay replacement until startLogging is called. Hmm, and why is os.linesep used in the logging? The log file should have been opened in text mode, in which case "\n" will get translated to the proper os-dependent form. I started to change the code, so I could submit a patch. I got the code out of CVS and am reading the documentation at http://twistedmatrix.com/documents/howto/coding-standard It says that the main test suite builder is in 'twisted.test.test_all' That module doesn't exist (can't import it) nor is the appropriate file present anywhere. And the hyperlink from that page yields "No Such Resource File not found." It then says Acceptance tests are all automated by the bin/accepttests but that program is in admin/accepttests I ran that for my Mac OS X machine, with 'open' as the WEBBROWSER setting (where does the '-b' option go, since open doesn't block .. do I pass it to 'accepttests'? Yes.) and /bin/true as my IRCCLIENT, since I wouldn't know what to do with one even assuming I had one. Anyway, after a while it gave this error /------ |#### |#### Starting mail test. |#### Output should be one email (postmaster@foo.bar) |#### and one bounce (postmaster@no.such.domain). |#### \------ Running Command: './admin/../bin/mktap mail --domain foo.bar=dump --user postmaster=postmaster --pop 18110' option --pop not a unique prefix Usage: mktap mail [options] Options: -p, --pop3= Port to start the POP3 server on (0 to disable). [default: 8110] -S, --pop3s= Port to start the POP3-over-SSL server on (0 to disable). [default: 0] -s, --smtp= Port to start the SMTP server on (0 to disable). [default: 8025] -r, --relay= relay mail we do not know how to handle to this IP, using the given path as a queue directory -c, --certificate= Certificate file to use for SSL connections -d, --domain= generate an SMTP/POP3 virtual domain which saves to "path" --version --help Display this help and exit. -u, --user= add a user/password to the last specified domains --bounce-to-postmaster undelivered mails are sent to the postmaster This creates a mail.tap file that can be used by twistd. Running Command: './admin/../bin/twistd -f mail.tap' Failed to load application: [Errno 2] No such file or directory: 'mail.tap' Traceback (most recent call last): File "./admin/accepttests", line 271, in ? runAllTests() File "./admin/accepttests", line 247, in runAllTests runMailTest() File "./admin/accepttests", line 204, in runMailTest s = smtplib.SMTP('127.0.0.1', 18026) File "/usr/local/lib/python2.3/smtplib.py", line 240, in __init__ (code, msg) = self.connect(host, port) File "/usr/local/lib/python2.3/smtplib.py", line 302, in connect raise socket.error, msg socket.error: (61, 'Connection refused') Hmmm.... Is 'admin/runtests' the correct script to run? I ran that, and got the following output ======================================================================== ======= FAILURE: testReadLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 193, in testReadLimit self.assertEquals(tServer.readThisSecond, 0) FailTest: 20 != 0 ======================================================================== ======= FAILURE: testWriteLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 152, in testWriteLimit self.assert_(abs(p.wrappedProtocol.paused - now - 1.0) < 0.1) FailTest ======================================================================== ======= FAILURE: testPackages (twisted.test.test_setup.CheckingPackagesTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_setup.py", line 44, in testPackages self.failUnlessEqual(l, []) FailTest: ['twisted.bugs', 'twisted.coils', 'twisted.eco', 'twisted.enterprise.userRequests', 'twisted.forum', 'twisted.inetd', 'twisted.issues', 'twisted.issues.ui', 'twisted.issues.ui.templates', 'twisted.lumberjack', 'twisted.metrics', 'twisted.pretzel', 'twisted.protocols.ldap', 'twisted.reality', 'twisted.reality.ui', 'twisted.secsh', 'twisted.test.interactive', 'twisted.web.blog', 'twisted.words.ui', 'twisted.words.ui.gateways'] != [] ======================================================================== ======= FAILURE: testFailing (twisted.test.test_tcp.LoopbackTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_tcp.py", line 171, in testFailing self.assert_(time.time() - start < 0.1) FailTest ======================================================================== ======= ERROR: testUnicodeTolerance (twisted.test.test_xml.MicroDOMTest) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/trial/unittest.py", line 165, in runOneTest method(testCase) File "/Users/dalke/cvses/Twisted/twisted/test/test_xml.py", line 326, in testUnicodeTolerance ud = microdom.parseString(s.encode('UTF-16')) File "./twisted/web/microdom.py", line 644, in parseString File "./twisted/web/microdom.py", line 609, in parse File "./twisted/protocols/sux.py", line 155, in dataReceived File "./twisted/protocols/sux.py", line 176, in do_begin File "./twisted/protocols/sux.py", line 108, in _parseError ParseError: <xmlfile />:1:1: First char of document ['\xfe'] wasn't < ======================================================================== ======= SKIPPED: test_modules (twisted.test.test_doc.DocCoverage) ------------------------------------------------------------------------ ------- Remove this line when you feel like writing docstrings. ------------------------------------------------------------------------ ------- Ran 494 tests in 227.667s FAILED (failures=4, errors=1, skips=1) Could not import twisted.test.test_conch: No module named Crypto.Cipher So I tried to rewrite the code given that it looks like the self-tests run reasonably well, but then ran into complications with this bit of code # Make sure we have some basic logging setup. This only works in cpython. try: logOwner except NameError: logOwner = LogOwner() ... # Prevent logfile from being erased on reload. This only works in cpython. try: logfile except NameError: logfile = NullFile() logerr = sys.stderr Okay, so we've got some code duplication here, and comment skew. I've fixed that up, and tidied up a few other bits of the code. And for the life of me I can't figure out why the log file should default (when no logging is enabled) to the NullFile rather than sys.stderr -- if you really want the NullFile, just pass it in. So I switched it to use sys.stderr. I then reran the 'admin/runtests' script and got ... some warnings and comments which were being supressed. /Users/dalke/cvses/Twisted/twisted/test/test_delay.py:24: DeprecationWarning: twisted.python.delay is deprecated. Please use reactor methods. from twisted.python import delay /Users/dalke/cvses/Twisted/twisted/protocols/dns.py:46: RuntimeWarning: PyCrypto not available - proceeding with non-cryptographically secure random source Enabling Multithreading. Resolver added ('64.105.156.138', 53) to server list Resolver added ('64.105.132.250', 53) to server list Also, I removed those os.linesep references, and the os module, and the needless string module. And turned 'file_protocol' into '_file_protocol' since it's for internal use only. Why's the Log pickleable? What happens if a cStringIO is passed in instead of a file? Or an outgoing network socket? Or a os.popen("lp")? It looks like Log.synchronized is old code that can be removed. Yes? Why does doc/examples/cursesclient.py set log.logfile directly? Shouldn't it call log.startLogging(log.NullFile()) ? It's the only other piece of code which references log.NullFile. Is 'discardLogs' the true inverse of startLogging? If so, it should add something to restore sys.stdout/sys.stderr if startLogging asked them to be changed. If not, where's the 'stopLogging' function? And 'discard' means to ignore logging? Or should it throw away the log files? The terminology is confusing. Anyway, the diff -u is attached for you all to review and correct. Oh, and with my changes, I now see the expected warning when I start up, and I see two twisted messages ... [Andrew-Dalkes-Computer:~/cvses/Twisted] dalke% python cansmi_rpc.py /usr/local/lib/python2.3/site-packages/openeye/oechem.py:5: RuntimeWarning: Python C API version mismatch for module _oechem: This Python has API version 1012, module _oechem has version 1011. import _oechem twisted.web.server.Site starting on 8080 Starting factory <twisted.web.server.Site instance at 0x640850> which tells me that those two messages ("Site starting" and "Starting factory") were being sent to never-never-land the whole time. Perhaps the latter shouldn't be present? Andrew dalke@dalkescientific.com
On Tue, 1 Apr 2003 07:00:53 -0500 Andrew Dalke <dalke@dalkescientific.com> wrote:
Fixed in CVS - warnings will be logged to stderr if no log file was specified.
Fixed doc in CVS.
Fixed in CVS.
Running admintests correctly is hard - I've never gotten the web distrib tests to pass. In general these tests are more for the release manager than for end users.
It looks like Log.synchronized is old code that can be removed. Yes?
Probably not. Basically, Twisted logging starts out with all log.msg() messages being discarded, and exceptions, errors and in CVS warnings, logged to stderr. startLogging() will set it so all messages get logged to the specified file-like object. -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
On Tue, Apr 01, 2003 at 07:00:53AM -0500, Andrew Dalke wrote:
Yeah, replacing showwarnings is the idiomatic way to override the display of warnings. The bit that initializes the default logfile to NullFile is something moshez and glyph wanted, and, for the record, something I'm against. (sorry glyph :-)
Oh, that's a bit out of date. Just run `./bin/trial -p twisted.test' if you want to run all of the Twisted tests. I'll update the doc.
Note that all developers aren't really expected to run these, it's super-dependant on your environment and is finicky about how exactly you start the script. I'll add this to the doc, as well. ... Oh, it seems itamar just fixed those issues with the coding standard.
Anyway, after a while it gave this error
I have no idea what this error means.
Hmmm.... Is 'admin/runtests' the correct script to run? I ran that, and got the following output
Yeah, `admin/runtests' just runs `bin/trial -p twisted.test', for convenience.
This happened because you didn't use the `-P' option to cvs update/checkout. Please put this in your ~/.cvsrc: """ update -d -P checkout -P """
I have no idea what the rest of the problems were about, though.
I wish this could be accepted, but unless glyph changes his mind, it probably won't. The usual response is to use twistd, but twistd isn't appropriate in all use-cases (it is in yours, however). The *reason*, IIRC, was that "you shouldn't spam unwanted stuff to STDIO", which I think is stupid. Application developers could notice spam to stdio, and, if they don't like it, startLogging to NullFile. (I've heard a lot more complaints about "Why don't I see any output!?" than "Why does Twisted write stuff to my stdio?") </rant> Sorry, I guess I'll stop beating a dead horse. :)
Well, it should probably be pickleable only when it _can_ be. :) i.e., __getstate__ could test for a `.name' attribute on the file object, or something. Handling stuff like StringIO might be a bit trickier without hardcoding an `isinstance(self.file, StringIO)' into it... Perhaps it could `try: cPickle.dumps(self.file)' to test if the file's pickleable in the case where it's not a named file ;-)
It looks like Log.synchronized is old code that can be removed. Yes?
No, I'm pretty sure this is so threaded code that writes to the log doesn't break.
Probably.
Well, if you want to switch your logging to something else (sys.stdout/stderr), then pass that something else to startLogging, probably.
Anyway, the diff -u is attached for you all to review and correct.
Well, no, usually people use twistd. Which you should, if you're writing a server. It handles logging, daemonization, and a whole slew of other things for you, and, contrary to what most people think, doesn't require the use of .taps (see the `-y' parameter). Anyway, thanks for the in-depth message, it was helpful. -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
On Tue, Apr 01, 2003 at 02:11:18PM -0500, Christopher Armstrong wrote:
Ok, so apparently I had forgotten that glyph *did* agree to log errors and warnings to STDIO, but when he implemented the change it didn't work. Sorry, glyph :) Itamar just checked in a fix so stuff gets logged to stderr. Hooray! -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tuesday, April 1, 2003, at 02:17 PM, Christopher Armstrong wrote:
Thank you, Itamar! Hooray! -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD4DBQE+if5XvVGR4uSOE2wRAk9NAJ9ORSTci/M4Eio4zN7TuoDOG8MdVwCWLgfa SSRjC5KXmJj1Ei9jd6hBSg== =xHFS -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tuesday, April 1, 2003, at 02:11 PM, Christopher Armstrong wrote:
The reason that moshez and I have it written this way is simple: we don't want library code generating spurious messages that your code may not want printed. However, I think that you're correct in criticizing it for throwing away warnings and tracebacks. Errors, even in library code, ought to be presented the same way they're normally presented.
As long as we're talking about sys.std*err*, and not std*out*, I think this is acceptable. I'd like to hear if moshez's has any objections too, but barring that, let's do it immediately.
The usual response is to use twistd, but twistd isn't appropriate in all use-cases (it is in yours, however).
This should be a FAQ. Q. Is using 'twistd' always appropriate? A. Not always, but it is in your case.
Oh, I heard a lot of complaints about it writing spurious messages to stdio before this change was made. Different people are unhappy, but people are unhappy either way :-) -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD8DBQE+if4svVGR4uSOE2wRArcOAKCKs4sHno57LtUWgB+U2C1Oc1X6qgCfbg5N qHg2Z9ZDNkGHddmnKvWEFBw= =FtOD -----END PGP SIGNATURE-----
Itamar Shtull-Trauring:
Fixed in CVS - warnings will be logged to stderr if no log file was specified.
Mmm, okay, I see the patch you did in CVS. One thing I don't like about the log system is that it goes into place on import, rather than after some explicit request to actually use the log. It isn't obvious anywhere that that import will make a system level change. - what if I've changed warnings.showwarning in my own code (or in some other 3rd party package). Where's the documentation which states that there will be a problem? - It's pervasive. That is, if I import twisted.lore (perhaps because I want it to use it for my own documentation system) it's still the case that warnings.showwarning gets replaced. There should be no reason for that. Are there any other system-level functions or settings which get tweaked by Twisted?
It looks like Log.synchronized is old code that can be removed. Yes?
Probably not
Ahh, I see. It's emulating the Java keyword. Hmm, I probably would have had a Log implementation which changed depending on of this was threaded or not, and have threaded calls forward the write/writeline via a Queue. There are only 4 places which use that, outside of some of the test code. Is it really that useful given how non-obvious it is? Also, I see that the other places which use a class with the synchronized attribute (like web/static.py) also call threadable.synchronize on the class, as in python/logfile.py:threadable.synchronize(LogFile) test/test_threadpool.py:threadable.synchronize(Counter) test/test_threads.py:threadable.synchronize(Counter) web/static.py:threadable.synchronize(FileTransfer) Notice that log.py's Log class, which has a 'synchronized' attribute, is not so initialized. This suggests there's either a bug (this class needs to be synchronized) or that that attribute is unneeded. Christopher Armstrong:
The bit that initializes the default logfile to NullFile is something moshez and glyph wanted
Actually, I don't care where the default logfile goes, I just care where my system warnings go. But as you pointed out in a later email, it's now sent to 'STDIO'. I still don't like that it goes into effect without me doing anything other than an import.
I have no idea what this error means.
Looking only at the error message, it means that: - the option parsing code does automatic prefix expansion, so that if the option is '--pop3' and the argument is '--pop' and no other option starts with '--pop' then it's elided to '--pop3'. This was what DEC machines did for VMS commands (as I recall) and it was annoying because if a new option is added (like '--popcorn') then scripts which assumed that '--pop' would always be unique, broke. - and a new option was added which started with the '--pop' prefix, breaking the code. - and no one has run those tests in a while, probably not since 10-Feb-03 when moshez added the following option. ["pop3s", "S", 0, "Port to start the POP3-over-SSL server on (0 to disable)."],
This happened because you didn't use the `-P' option to cvs update/checkout. Please put this in your ~/.cvsrc:
Ummmm, okay, done, and those errors go away. The page at http://twistedmatrix.com/developers/cvs should be updated to mention this.
I have no idea what the rest of the problems were about, though.
Here's the full set of tracebacks ======================================================================== ======= FAILURE: testReadLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 193, in testReadLimit self.assertEquals(tServer.readThisSecond, 0) FailTest: 20 != 0 No clue. A timing issue? ======================================================================== ======= FAILURE: testWriteLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 152, in testWriteLimit self.assert_(abs(p.wrappedProtocol.paused - now - 1.0) < 0.1) FailTest Related to the previous case? ======================================================================== ======= FAILURE: testFailing (twisted.test.test_tcp.LoopbackTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_tcp.py", line 171, in testFailing self.assert_(time.time() - start < 0.1) FailTest Looks like it takes more than 0.1 seconds for me to fail that test. On this box (OS X), a connect looks like it starts off with an IPv6 request then tries 127.0.0.1 then tries ... an IP address I got a few weeks ago. Strange. That's on another network, which is firewalled from here. So that's probably where the delay comes in. [Andrew-Dalkes-Computer:~/cvses/Twisted] dalke% time telnet localhost 69 Trying ::1... telnet: connect to address ::1: Connection refused Trying 127.0.0.1... telnet: connect to address 127.0.0.1: Connection refused Trying 207.225.60.130... telnet: connect to address 207.225.60.130: Connection refused telnet: Unable to connect to remote host 0.000u 0.020s 0:00.46 4.3% 0+0k 0+0io 0pf+0w ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/trial/unittest.py", line 165, in runOneTest method(testCase) File "/Users/dalke/cvses/Twisted/twisted/test/test_process.py", line 140, in testEcho self.assertEquals(len(p.buffer), len(p.s * 10)) AttributeError: EchoProtocol instance has no attribute 'buffer' Trying to track that down, I see that twisted/internet/interfaces.py has mention of @see: C{twisted.protocols.protocol.ProcessProtocol} but twisted/protocols/protocol.py says """Deprecated - use twisted.internet.protocol instead. Anyway, the only reason I can see this error happened is if EchoProtocol's connectionMade wasn't called. I simply don't understand the code well enough to debug it right now. ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback! exceptions.OSError, [Errno 35] Resource temporarily unavailable ./twisted/internet/process.py:281:__init__ ./twisted/internet/protocol.py:290:makeConnection /Users/dalke/cvses/Twisted/twisted/test/ test_process.py:82:connectionMade ./twisted/internet/process.py:358:write ./twisted/internet/process.py:126:write ./twisted/internet/abstract.py:145:write ./twisted/internet/process.py:111:writeSomeData ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback! exceptions.AttributeError, EchoProtocol instance has no attribute 'buffer' ./twisted/internet/default.py:467:doSelect ./twisted/internet/process.py:345:doRead ./twisted/internet/fdesc.py:58:readFromFD /Users/dalke/cvses/Twisted/twisted/test/test_process.py:86:outReceived ======================================================================== ======= ERROR: testUnicodeTolerance (twisted.test.test_xml.MicroDOMTest) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/trial/unittest.py", line 165, in runOneTest method(testCase) File "/Users/dalke/cvses/Twisted/twisted/test/test_xml.py", line 326, in testUnicodeTolerance ud = microdom.parseString(s.encode('UTF-16')) File "/Users/dalke/cvses/Twisted/twisted/web/microdom.py", line 648, in parseString return parse(StringIO(st), *args, **kw) File "/Users/dalke/cvses/Twisted/twisted/web/microdom.py", line 613, in parse mdp.dataReceived(readable.getvalue()) File "./twisted/protocols/sux.py", line 155, in dataReceived File "./twisted/protocols/sux.py", line 176, in do_begin File "./twisted/protocols/sux.py", line 108, in _parseError ParseError: <xmlfile />:1:1: First char of document ['\xfe'] wasn't < \xfe is the byte order marker. This test started with s = "<foo><bar><baz /></bar></foo>" then encoded it as UTF-16, which puts the BOM at the front. So of course the string doesn't start with a '<'.
The *reason*, IIRC, was that "you shouldn't spam unwanted stuff to STDIO"
Again, I realize this has been changed. Just wanted to note that system warnings about API differences are wanted, as well as warnings about deprecations, etc.
Well, it should probably be pickleable only when it _can_ be. :) i.e.,
That didn't answer my question of why it needs to be pickled. I suppose it's part of the App, which saves complete state via a pickle? Err, it can't, because that's a module variable. In any case, the cleaner way to fix it is to have a specialized replacement called instead of the native open call, and have it store the arguments so that the unpickling gets the correct calls, and allow backwards compatibility with if isinstance(logfile, file): logfile = PickleableFile(logfile)
Well, no, usually people use twistd. Which you should, if you're writing a server.
I'm just working my way through the example, and it doesn't use twistd, so I didn't. As mentioned, I don't like how system settings are changed on an import, much less without documentation which says this will happen. If everything server related should be done in the context of twistd, then that warnings.showwarning replacement should only be done when twistd is used, which is why the patch I sent only made the switch when startLogging was called. The solution I see now, which is that showwarnings calls the errlog instead of the msg log, still isn't the right behaviour, IMO, if only because you are changing the format of the error messages. At the very least you should call warnings.formatwarning instead of building your own warning message. Oh, and the code should be that if file is not None, to use the file handle passed in to showwarnings, and not the error log, that is, replace twisted/python/log.py from def showwarning(message, category, filename, lineno, file=None): err('''\ WARNING: %s:: %s file: %s; line: %s ''' % (category, indent(message), filename, lineno)) to def showwarning(message, category, filename, lineno, file=None): m = warnings.formatwarning(message, category, filename, lineno) if file is None: err(m) else: file.write(m) Finally, I noticed that other part of my patch were not accepted. For example, the use of os.linesep is incorrect. The log file is opened in text mode, so "\n" will be converted to the appropriate byte representation for the given platform. In other words, logerr.write(str(stuff)+os.linesep) should be logerr.write(str(stuff)+"\n") I also did some things to clean up the code, like getting rid of unneeded module imports (like string) and replacing import cStringIO ... StringIO = cStringIO del cStringIO with import cStringIO as StringIO I noticed none of these were accepted. What should I do to make these sorts of changes more acceptable? After all, the point of a good unit test suite is to make it easy for people to refactor and clean up existing code. All the tests passed identically before and after my changes. I could, for instance, have split up the patch into several parts. However, part of what I did was to replace the warnings.showwarning code only once, which required a test against a reload (as is done in two other parts for the code) so I moved those into a single change and fixed the comments for why it was done. Andrew dalke@dalkescientific.com
On Tue, 1 Apr 2003 16:48:01 -0500 Andrew Dalke <dalke@dalkescientific.com> wrote:
I agree that this is bad. If you complain enough maybe glyph will listen to reason.
Are there any other system-level functions or settings which get tweaked by Twisted?
Not that I can recall.
There are only 4 places which use that, outside of some of the test code. Is it really that useful given how non-obvious it is?
No. We need to have thread-safe logging.
Indeed.
I still don't like that it goes into effect without me doing anything other than an import.
Yes. Its glyph's fault, again.
Yes, they only get run during releases. Jean-Paul fixed the --pop issue in CVS I think. Some of the failed tests look like timing issues, yes.
Gar. I wonder why this isn't showing on the Max OS X buildbot.
Typo - fixed in CVS. Any bugs we can reproduce and are easily fixable will be fixed by next release, e.g. the dom one.
We should have logging docs soon.
Again, I agree, bug glyph.
The idea was to have more informative messages. Can you put in something comparing the two formats?
Done, at least partially.
I noticed none of these were accepted.
Not really, I just didn't get around to reading the patch. I did some of these in CVS.
What should I do to make these sorts of changes more acceptable?
They were not bad, it seems, we just don't have time to deal with all of them... I have a huge queue waiting for me :( We do appreciate your efforts.
Yes, but behaviour was changed I think? Possibly in a better way, but changing behaviour takes more mental work on our part. -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
On Tue, Apr 01, 2003 at 10:45:23PM -0500, Itamar Shtull-Trauring wrote:
Well, I was the one who made this change, and there's no particular philosophical reasons behind it. I agree moving it to twistd would be good. -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
On Wed, 2 Apr 2003 01:25:20 -0500 Christopher Armstrong <radix@twistedmatrix.com> wrote:
Why don't you do that then? -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Wednesday, April 2, 2003, at 01:25 AM, Christopher Armstrong wrote: [... import does bad stuff ...]
Shouldn't this just be in startLogging? -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD8DBQE+i0XQvVGR4uSOE2wRAu3KAKCOsnaYD58ywJT61CbsHxSi3N+qXACeI2Yn BE4vqsLYA3ZSauUPkNfQHzs= =74r3 -----END PGP SIGNATURE-----
On Wed, 2 Apr 2003 15:19:24 -0500 Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
Shouldn't this just be in startLogging?
I'm pretty sure startLogging is called at some point on import? Or how is the default logging set up? -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
On Tue, 1 Apr 2003 07:00:53 -0500 Andrew Dalke <dalke@dalkescientific.com> wrote:
Fixed in CVS - warnings will be logged to stderr if no log file was specified.
Fixed doc in CVS.
Fixed in CVS.
Running admintests correctly is hard - I've never gotten the web distrib tests to pass. In general these tests are more for the release manager than for end users.
It looks like Log.synchronized is old code that can be removed. Yes?
Probably not. Basically, Twisted logging starts out with all log.msg() messages being discarded, and exceptions, errors and in CVS warnings, logged to stderr. startLogging() will set it so all messages get logged to the specified file-like object. -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
On Tue, Apr 01, 2003 at 07:00:53AM -0500, Andrew Dalke wrote:
Yeah, replacing showwarnings is the idiomatic way to override the display of warnings. The bit that initializes the default logfile to NullFile is something moshez and glyph wanted, and, for the record, something I'm against. (sorry glyph :-)
Oh, that's a bit out of date. Just run `./bin/trial -p twisted.test' if you want to run all of the Twisted tests. I'll update the doc.
Note that all developers aren't really expected to run these, it's super-dependant on your environment and is finicky about how exactly you start the script. I'll add this to the doc, as well. ... Oh, it seems itamar just fixed those issues with the coding standard.
Anyway, after a while it gave this error
I have no idea what this error means.
Hmmm.... Is 'admin/runtests' the correct script to run? I ran that, and got the following output
Yeah, `admin/runtests' just runs `bin/trial -p twisted.test', for convenience.
This happened because you didn't use the `-P' option to cvs update/checkout. Please put this in your ~/.cvsrc: """ update -d -P checkout -P """
I have no idea what the rest of the problems were about, though.
I wish this could be accepted, but unless glyph changes his mind, it probably won't. The usual response is to use twistd, but twistd isn't appropriate in all use-cases (it is in yours, however). The *reason*, IIRC, was that "you shouldn't spam unwanted stuff to STDIO", which I think is stupid. Application developers could notice spam to stdio, and, if they don't like it, startLogging to NullFile. (I've heard a lot more complaints about "Why don't I see any output!?" than "Why does Twisted write stuff to my stdio?") </rant> Sorry, I guess I'll stop beating a dead horse. :)
Well, it should probably be pickleable only when it _can_ be. :) i.e., __getstate__ could test for a `.name' attribute on the file object, or something. Handling stuff like StringIO might be a bit trickier without hardcoding an `isinstance(self.file, StringIO)' into it... Perhaps it could `try: cPickle.dumps(self.file)' to test if the file's pickleable in the case where it's not a named file ;-)
It looks like Log.synchronized is old code that can be removed. Yes?
No, I'm pretty sure this is so threaded code that writes to the log doesn't break.
Probably.
Well, if you want to switch your logging to something else (sys.stdout/stderr), then pass that something else to startLogging, probably.
Anyway, the diff -u is attached for you all to review and correct.
Well, no, usually people use twistd. Which you should, if you're writing a server. It handles logging, daemonization, and a whole slew of other things for you, and, contrary to what most people think, doesn't require the use of .taps (see the `-y' parameter). Anyway, thanks for the in-depth message, it was helpful. -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
On Tue, Apr 01, 2003 at 02:11:18PM -0500, Christopher Armstrong wrote:
Ok, so apparently I had forgotten that glyph *did* agree to log errors and warnings to STDIO, but when he implemented the change it didn't work. Sorry, glyph :) Itamar just checked in a fix so stuff gets logged to stderr. Hooray! -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tuesday, April 1, 2003, at 02:17 PM, Christopher Armstrong wrote:
Thank you, Itamar! Hooray! -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD4DBQE+if5XvVGR4uSOE2wRAk9NAJ9ORSTci/M4Eio4zN7TuoDOG8MdVwCWLgfa SSRjC5KXmJj1Ei9jd6hBSg== =xHFS -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tuesday, April 1, 2003, at 02:11 PM, Christopher Armstrong wrote:
The reason that moshez and I have it written this way is simple: we don't want library code generating spurious messages that your code may not want printed. However, I think that you're correct in criticizing it for throwing away warnings and tracebacks. Errors, even in library code, ought to be presented the same way they're normally presented.
As long as we're talking about sys.std*err*, and not std*out*, I think this is acceptable. I'd like to hear if moshez's has any objections too, but barring that, let's do it immediately.
The usual response is to use twistd, but twistd isn't appropriate in all use-cases (it is in yours, however).
This should be a FAQ. Q. Is using 'twistd' always appropriate? A. Not always, but it is in your case.
Oh, I heard a lot of complaints about it writing spurious messages to stdio before this change was made. Different people are unhappy, but people are unhappy either way :-) -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD8DBQE+if4svVGR4uSOE2wRArcOAKCKs4sHno57LtUWgB+U2C1Oc1X6qgCfbg5N qHg2Z9ZDNkGHddmnKvWEFBw= =FtOD -----END PGP SIGNATURE-----
Itamar Shtull-Trauring:
Fixed in CVS - warnings will be logged to stderr if no log file was specified.
Mmm, okay, I see the patch you did in CVS. One thing I don't like about the log system is that it goes into place on import, rather than after some explicit request to actually use the log. It isn't obvious anywhere that that import will make a system level change. - what if I've changed warnings.showwarning in my own code (or in some other 3rd party package). Where's the documentation which states that there will be a problem? - It's pervasive. That is, if I import twisted.lore (perhaps because I want it to use it for my own documentation system) it's still the case that warnings.showwarning gets replaced. There should be no reason for that. Are there any other system-level functions or settings which get tweaked by Twisted?
It looks like Log.synchronized is old code that can be removed. Yes?
Probably not
Ahh, I see. It's emulating the Java keyword. Hmm, I probably would have had a Log implementation which changed depending on of this was threaded or not, and have threaded calls forward the write/writeline via a Queue. There are only 4 places which use that, outside of some of the test code. Is it really that useful given how non-obvious it is? Also, I see that the other places which use a class with the synchronized attribute (like web/static.py) also call threadable.synchronize on the class, as in python/logfile.py:threadable.synchronize(LogFile) test/test_threadpool.py:threadable.synchronize(Counter) test/test_threads.py:threadable.synchronize(Counter) web/static.py:threadable.synchronize(FileTransfer) Notice that log.py's Log class, which has a 'synchronized' attribute, is not so initialized. This suggests there's either a bug (this class needs to be synchronized) or that that attribute is unneeded. Christopher Armstrong:
The bit that initializes the default logfile to NullFile is something moshez and glyph wanted
Actually, I don't care where the default logfile goes, I just care where my system warnings go. But as you pointed out in a later email, it's now sent to 'STDIO'. I still don't like that it goes into effect without me doing anything other than an import.
I have no idea what this error means.
Looking only at the error message, it means that: - the option parsing code does automatic prefix expansion, so that if the option is '--pop3' and the argument is '--pop' and no other option starts with '--pop' then it's elided to '--pop3'. This was what DEC machines did for VMS commands (as I recall) and it was annoying because if a new option is added (like '--popcorn') then scripts which assumed that '--pop' would always be unique, broke. - and a new option was added which started with the '--pop' prefix, breaking the code. - and no one has run those tests in a while, probably not since 10-Feb-03 when moshez added the following option. ["pop3s", "S", 0, "Port to start the POP3-over-SSL server on (0 to disable)."],
This happened because you didn't use the `-P' option to cvs update/checkout. Please put this in your ~/.cvsrc:
Ummmm, okay, done, and those errors go away. The page at http://twistedmatrix.com/developers/cvs should be updated to mention this.
I have no idea what the rest of the problems were about, though.
Here's the full set of tracebacks ======================================================================== ======= FAILURE: testReadLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 193, in testReadLimit self.assertEquals(tServer.readThisSecond, 0) FailTest: 20 != 0 No clue. A timing issue? ======================================================================== ======= FAILURE: testWriteLimit (twisted.test.test_policies.ThrottlingTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_policies.py", line 152, in testWriteLimit self.assert_(abs(p.wrappedProtocol.paused - now - 1.0) < 0.1) FailTest Related to the previous case? ======================================================================== ======= FAILURE: testFailing (twisted.test.test_tcp.LoopbackTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/test/test_tcp.py", line 171, in testFailing self.assert_(time.time() - start < 0.1) FailTest Looks like it takes more than 0.1 seconds for me to fail that test. On this box (OS X), a connect looks like it starts off with an IPv6 request then tries 127.0.0.1 then tries ... an IP address I got a few weeks ago. Strange. That's on another network, which is firewalled from here. So that's probably where the delay comes in. [Andrew-Dalkes-Computer:~/cvses/Twisted] dalke% time telnet localhost 69 Trying ::1... telnet: connect to address ::1: Connection refused Trying 127.0.0.1... telnet: connect to address 127.0.0.1: Connection refused Trying 207.225.60.130... telnet: connect to address 207.225.60.130: Connection refused telnet: Unable to connect to remote host 0.000u 0.020s 0:00.46 4.3% 0+0k 0+0io 0pf+0w ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/trial/unittest.py", line 165, in runOneTest method(testCase) File "/Users/dalke/cvses/Twisted/twisted/test/test_process.py", line 140, in testEcho self.assertEquals(len(p.buffer), len(p.s * 10)) AttributeError: EchoProtocol instance has no attribute 'buffer' Trying to track that down, I see that twisted/internet/interfaces.py has mention of @see: C{twisted.protocols.protocol.ProcessProtocol} but twisted/protocols/protocol.py says """Deprecated - use twisted.internet.protocol instead. Anyway, the only reason I can see this error happened is if EchoProtocol's connectionMade wasn't called. I simply don't understand the code well enough to debug it right now. ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback! exceptions.OSError, [Errno 35] Resource temporarily unavailable ./twisted/internet/process.py:281:__init__ ./twisted/internet/protocol.py:290:makeConnection /Users/dalke/cvses/Twisted/twisted/test/ test_process.py:82:connectionMade ./twisted/internet/process.py:358:write ./twisted/internet/process.py:126:write ./twisted/internet/abstract.py:145:write ./twisted/internet/process.py:111:writeSomeData ======================================================================== ======= ERROR: testEcho (twisted.test.test_process.ProcessTestCase) ------------------------------------------------------------------------ ------- Traceback! exceptions.AttributeError, EchoProtocol instance has no attribute 'buffer' ./twisted/internet/default.py:467:doSelect ./twisted/internet/process.py:345:doRead ./twisted/internet/fdesc.py:58:readFromFD /Users/dalke/cvses/Twisted/twisted/test/test_process.py:86:outReceived ======================================================================== ======= ERROR: testUnicodeTolerance (twisted.test.test_xml.MicroDOMTest) ------------------------------------------------------------------------ ------- Traceback (most recent call last): File "/Users/dalke/cvses/Twisted/twisted/trial/unittest.py", line 165, in runOneTest method(testCase) File "/Users/dalke/cvses/Twisted/twisted/test/test_xml.py", line 326, in testUnicodeTolerance ud = microdom.parseString(s.encode('UTF-16')) File "/Users/dalke/cvses/Twisted/twisted/web/microdom.py", line 648, in parseString return parse(StringIO(st), *args, **kw) File "/Users/dalke/cvses/Twisted/twisted/web/microdom.py", line 613, in parse mdp.dataReceived(readable.getvalue()) File "./twisted/protocols/sux.py", line 155, in dataReceived File "./twisted/protocols/sux.py", line 176, in do_begin File "./twisted/protocols/sux.py", line 108, in _parseError ParseError: <xmlfile />:1:1: First char of document ['\xfe'] wasn't < \xfe is the byte order marker. This test started with s = "<foo><bar><baz /></bar></foo>" then encoded it as UTF-16, which puts the BOM at the front. So of course the string doesn't start with a '<'.
The *reason*, IIRC, was that "you shouldn't spam unwanted stuff to STDIO"
Again, I realize this has been changed. Just wanted to note that system warnings about API differences are wanted, as well as warnings about deprecations, etc.
Well, it should probably be pickleable only when it _can_ be. :) i.e.,
That didn't answer my question of why it needs to be pickled. I suppose it's part of the App, which saves complete state via a pickle? Err, it can't, because that's a module variable. In any case, the cleaner way to fix it is to have a specialized replacement called instead of the native open call, and have it store the arguments so that the unpickling gets the correct calls, and allow backwards compatibility with if isinstance(logfile, file): logfile = PickleableFile(logfile)
Well, no, usually people use twistd. Which you should, if you're writing a server.
I'm just working my way through the example, and it doesn't use twistd, so I didn't. As mentioned, I don't like how system settings are changed on an import, much less without documentation which says this will happen. If everything server related should be done in the context of twistd, then that warnings.showwarning replacement should only be done when twistd is used, which is why the patch I sent only made the switch when startLogging was called. The solution I see now, which is that showwarnings calls the errlog instead of the msg log, still isn't the right behaviour, IMO, if only because you are changing the format of the error messages. At the very least you should call warnings.formatwarning instead of building your own warning message. Oh, and the code should be that if file is not None, to use the file handle passed in to showwarnings, and not the error log, that is, replace twisted/python/log.py from def showwarning(message, category, filename, lineno, file=None): err('''\ WARNING: %s:: %s file: %s; line: %s ''' % (category, indent(message), filename, lineno)) to def showwarning(message, category, filename, lineno, file=None): m = warnings.formatwarning(message, category, filename, lineno) if file is None: err(m) else: file.write(m) Finally, I noticed that other part of my patch were not accepted. For example, the use of os.linesep is incorrect. The log file is opened in text mode, so "\n" will be converted to the appropriate byte representation for the given platform. In other words, logerr.write(str(stuff)+os.linesep) should be logerr.write(str(stuff)+"\n") I also did some things to clean up the code, like getting rid of unneeded module imports (like string) and replacing import cStringIO ... StringIO = cStringIO del cStringIO with import cStringIO as StringIO I noticed none of these were accepted. What should I do to make these sorts of changes more acceptable? After all, the point of a good unit test suite is to make it easy for people to refactor and clean up existing code. All the tests passed identically before and after my changes. I could, for instance, have split up the patch into several parts. However, part of what I did was to replace the warnings.showwarning code only once, which required a test against a reload (as is done in two other parts for the code) so I moved those into a single change and fixed the comments for why it was done. Andrew dalke@dalkescientific.com
On Tue, 1 Apr 2003 16:48:01 -0500 Andrew Dalke <dalke@dalkescientific.com> wrote:
I agree that this is bad. If you complain enough maybe glyph will listen to reason.
Are there any other system-level functions or settings which get tweaked by Twisted?
Not that I can recall.
There are only 4 places which use that, outside of some of the test code. Is it really that useful given how non-obvious it is?
No. We need to have thread-safe logging.
Indeed.
I still don't like that it goes into effect without me doing anything other than an import.
Yes. Its glyph's fault, again.
Yes, they only get run during releases. Jean-Paul fixed the --pop issue in CVS I think. Some of the failed tests look like timing issues, yes.
Gar. I wonder why this isn't showing on the Max OS X buildbot.
Typo - fixed in CVS. Any bugs we can reproduce and are easily fixable will be fixed by next release, e.g. the dom one.
We should have logging docs soon.
Again, I agree, bug glyph.
The idea was to have more informative messages. Can you put in something comparing the two formats?
Done, at least partially.
I noticed none of these were accepted.
Not really, I just didn't get around to reading the patch. I did some of these in CVS.
What should I do to make these sorts of changes more acceptable?
They were not bad, it seems, we just don't have time to deal with all of them... I have a huge queue waiting for me :( We do appreciate your efforts.
Yes, but behaviour was changed I think? Possibly in a better way, but changing behaviour takes more mental work on our part. -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
On Tue, Apr 01, 2003 at 10:45:23PM -0500, Itamar Shtull-Trauring wrote:
Well, I was the one who made this change, and there's no particular philosophical reasons behind it. I agree moving it to twistd would be good. -- Twisted | Christopher Armstrong: International Man of Twistery Radix | Release Manager, Twisted Project ---------+ http://twistedmatrix.com/users/radix.twistd/
On Wed, 2 Apr 2003 01:25:20 -0500 Christopher Armstrong <radix@twistedmatrix.com> wrote:
Why don't you do that then? -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Wednesday, April 2, 2003, at 01:25 AM, Christopher Armstrong wrote: [... import does bad stuff ...]
Shouldn't this just be in startLogging? -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.2.1 (Darwin) iD8DBQE+i0XQvVGR4uSOE2wRAu3KAKCOsnaYD58ywJT61CbsHxSi3N+qXACeI2Yn BE4vqsLYA3ZSauUPkNfQHzs= =74r3 -----END PGP SIGNATURE-----
On Wed, 2 Apr 2003 15:19:24 -0500 Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
Shouldn't this just be in startLogging?
I'm pretty sure startLogging is called at some point on import? Or how is the default logging set up? -- Itamar Shtull-Trauring http://itamarst.org/ http://www.zoteca.com -- Python & Twisted consulting
participants (5)
-
Andrew Dalke -
Christopher Armstrong -
Glyph Lefkowitz -
Itamar Shtull-Trauring -
Itamar Shtull-Trauring