[Shtoom] what happens to stdout in text-mode UI?

[Zooko Wilcox-O'Hearn]

I've added some code like this to protocol.py:

LOG=open("protocol.py.log", "w")
...
     def sendFirstData(self):
         LOG.write("about to raise \"HELLO WORLD!  PLEASE SEE ME!  I am  
in sendFirstData()!\"\n")
         raise "HELLO WORLD!  PLEASE SEE ME!  I am in sendFirstData()!"

When I run this code on Linux, I get the following result:

2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] baseaudio: reopen
2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] ossaudiodev opening
2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] initialising  
playout <shtoom.audio.playout.BrainDeadPlayout instance at 0x406b53ec>
2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] call Start  
'CallCookie1' ('192.168.1.100', 47944)
2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] Traceback (most  
recent call last):
           File  
"/home/zooko/instdirs/twisted/lib/python2.3/site-packages/twisted/ 
python/context.py", line 31, in callWithContext
             return func(*args,**kw)
           File  
"/home/zooko/instdirs/twisted/lib/python2.3/site-packages/twisted/ 
internet/d
 >>
 >>
 >> HACM pion:~/tmp$ l
drwxrwsr-x    2 zooko    zooko         112 Oct  4 09:15 ./.
drwxr-sr-x  138 zooko    zooko       14200 Oct  4 09:16 ./..
-rw-rw-r--    1 zooko    zooko           0 Oct  4 09:17 ./sip.py.log
-rw-rw-r--    1 zooko    zooko          72 Oct  4 09:17  
./protocol.py.log
HACM pion:~/tmp$ cat protocol.py.log
about to raise "HELLO WORLD!  PLEASE SEE ME!  I am in sendFirstData()!"


When I run this code on OSX, I get the following result:

2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] Allow-Events:  
telephone-event
2004/10/04 09:17 ADT [shtoom.sip.SipProtocol (UDP)] User-Agent:  
Shtoom/0.3alpha0
2004/10/04 09:17 ADT [shtoINCOMING CALL: "None" <sip:None>;tag=01ee022d
Type 'accept' to accept, 'reject' to reject
accept
 >>
 >>
 >>
 >> ^C^C
HACK draco:~/tmp$
HACK draco:~/tmp$
HACK draco:~/tmp$
HACK draco:~/tmp$ l
drwxr-xr-x  243 zooko  staff  8262  4 Oct 08:09 ./..
-rw-rw-r--    1 zooko  staff     0  4 Oct 08:55 ./sip.py.log
drwxrwxr-x    4 zooko  staff   136  4 Oct 09:15 ./.
-rw-rw-r--    1 zooko  staff    72  4 Oct 09:17 ./protocol.py.log
HACK draco:~/tmp$ cat protocol.py.log
about to raise "HELLO WORLD!  PLEASE SEE ME!  I am in sendFirstData()!"


It appears to me that uncaught exceptions fall into a race condition or  
other inconsistency in the Shtoom/Twisted logging system.

This is with the text ui.  I guess the process's stdout is doing double  
duty here.  Python's sys.stdout is redirected to the logger, which  
prepends a timestamp and then sends to the process's real stdout.  Also  
the text ui has connected to the process's stdin/stdout as a Python  
transport and is using it for UI.

What do you think?  Should we just eliminate the concept of logging to  
stdout when you are also using the text-mode UI, and make a logfile for  
text-mode UI?

Note that this problem isn't only for uncaught exceptions.  In fact, I  
added a "print" statement before the "raise" statement and re-ran this  
experiment.  This time nothing about the LOG/print/raise appeared at  
all in stdout, although the expected line still appeared in the log  
file.

Regards,

Zooko